[INFO] fetching crate ramu_rs 0.1.1... [INFO] testing ramu_rs-0.1.1 against 1.91.0 for beta-1.92-2 [INFO] extracting crate ramu_rs 0.1.1 into /workspace/builds/worker-5-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-5-tc1/source/Cargo.toml [INFO] validating manifest of crates.io crate ramu_rs 0.1.1 on toolchain 1.91.0 [INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+1.91.0" "metadata" "--manifest-path" "Cargo.toml" "--no-deps", kill_on_drop: false }` [INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+1.91.0" "generate-lockfile" "--manifest-path" "Cargo.toml", kill_on_drop: false }` [INFO] [stderr] Blocking waiting for file lock on package cache [INFO] [stderr] Updating crates.io index [INFO] [stderr] Blocking waiting for file lock on package cache [INFO] [stderr] Locking 62 packages to latest compatible versions [INFO] [stderr] Adding enum-as-inner v0.5.1 (available: v0.6.1) [INFO] [stderr] Adding num_enum v0.5.11 (available: v0.7.5) [INFO] [stderr] Adding toml v0.5.11 (available: v0.9.8) [INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+1.91.0" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }` [INFO] [stderr] Blocking waiting for file lock on package cache [INFO] [stderr] Downloading crates ... [INFO] [stderr] Downloaded codespan-reporting v0.13.1 [INFO] [stderr] Downloaded cxxbridge-flags v1.0.187 [INFO] [stderr] Downloaded enum-as-inner v0.5.1 [INFO] [stderr] Downloaded clap v4.5.51 [INFO] [stderr] Downloaded scratch v1.0.9 [INFO] [stderr] Downloaded link-cplusplus v1.0.12 [INFO] [stderr] Downloaded cxxbridge-cmd v1.0.187 [INFO] [stderr] Downloaded cxxbridge-macro v1.0.187 [INFO] [stderr] Downloaded cxx v1.0.187 [INFO] [stderr] Downloaded clap_builder v4.5.51 [INFO] [stderr] Downloaded cxx-build v1.0.187 [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-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:4848fb76d95f26979359cc7e45710b1dbc8f3acb7aeedee7c460d7702230f228" "/opt/rustwide/cargo-home/bin/cargo" "+1.91.0" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }` [INFO] [stdout] 9fdc5384ab2c8ac8aa779fa8df12d1445c7836456e87e4a9561d78b2583cbbbe [INFO] running `Command { std: "docker" "start" "-a" "9fdc5384ab2c8ac8aa779fa8df12d1445c7836456e87e4a9561d78b2583cbbbe", kill_on_drop: false }` [INFO] running `Command { std: "docker" "inspect" "9fdc5384ab2c8ac8aa779fa8df12d1445c7836456e87e4a9561d78b2583cbbbe", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "9fdc5384ab2c8ac8aa779fa8df12d1445c7836456e87e4a9561d78b2583cbbbe", kill_on_drop: false }` [INFO] [stdout] 9fdc5384ab2c8ac8aa779fa8df12d1445c7836456e87e4a9561d78b2583cbbbe [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc1/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=warn" "-e" "RUSTDOCFLAGS=--cap-lints=warn" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:4848fb76d95f26979359cc7e45710b1dbc8f3acb7aeedee7c460d7702230f228" "/opt/rustwide/cargo-home/bin/cargo" "+1.91.0" "build" "--frozen" "--message-format=json", kill_on_drop: false }` [INFO] [stdout] b2ca4e1ce22aade6ff4ef0db5b521e378c11cb7d7cb4e6fde4b30a8f278a0a55 [INFO] running `Command { std: "docker" "start" "-a" "b2ca4e1ce22aade6ff4ef0db5b521e378c11cb7d7cb4e6fde4b30a8f278a0a55", kill_on_drop: false }` [INFO] [stderr] Compiling equivalent v1.0.2 [INFO] [stderr] Compiling hashbrown v0.16.0 [INFO] [stderr] Compiling syn v1.0.109 [INFO] [stderr] Compiling toml_datetime v0.6.11 [INFO] [stderr] Compiling winnow v0.5.40 [INFO] [stderr] Compiling cxxbridge-flags v1.0.187 [INFO] [stderr] Compiling tracing-core v0.1.34 [INFO] [stderr] Compiling regex-automata v0.4.13 [INFO] [stderr] Compiling link-cplusplus v1.0.12 [INFO] [stderr] Compiling thread_local v1.1.9 [INFO] [stderr] Compiling sharded-slab v0.1.7 [INFO] [stderr] Compiling heck v0.4.1 [INFO] [stderr] Compiling foldhash v0.2.0 [INFO] [stderr] Compiling syn v2.0.108 [INFO] [stderr] Compiling nu-ansi-term v0.50.3 [INFO] [stderr] Compiling cxx v1.0.187 [INFO] [stderr] Compiling tracing-log v0.2.0 [INFO] [stderr] Compiling indexmap v2.12.0 [INFO] [stderr] Compiling enum-as-inner v0.5.1 [INFO] [stderr] Compiling matchers v0.2.0 [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 serde_derive v1.0.228 [INFO] [stderr] Compiling tracing-attributes v0.1.30 [INFO] [stderr] Compiling cxxbridge-macro v1.0.187 [INFO] [stderr] Compiling num_enum v0.5.11 [INFO] [stderr] Compiling tracing v0.1.41 [INFO] [stderr] Compiling tracing-subscriber v0.3.20 [INFO] [stderr] Compiling serde v1.0.228 [INFO] [stderr] Compiling toml v0.5.11 [INFO] [stderr] Compiling ramu_rs v0.1.1 (/opt/rustwide/workdir) [INFO] [stderr] Finished `dev` profile [unoptimized + debuginfo] target(s) in 18.75s [INFO] running `Command { std: "docker" "inspect" "b2ca4e1ce22aade6ff4ef0db5b521e378c11cb7d7cb4e6fde4b30a8f278a0a55", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "b2ca4e1ce22aade6ff4ef0db5b521e378c11cb7d7cb4e6fde4b30a8f278a0a55", kill_on_drop: false }` [INFO] [stdout] b2ca4e1ce22aade6ff4ef0db5b521e378c11cb7d7cb4e6fde4b30a8f278a0a55 [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc1/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=warn" "-e" "RUSTDOCFLAGS=--cap-lints=warn" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:4848fb76d95f26979359cc7e45710b1dbc8f3acb7aeedee7c460d7702230f228" "/opt/rustwide/cargo-home/bin/cargo" "+1.91.0" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }` [INFO] [stdout] 4d57899c8face10e0dfe491ef2b52e8c2f4410918df6dcc99dcf23321e9a3e8e [INFO] running `Command { std: "docker" "start" "-a" "4d57899c8face10e0dfe491ef2b52e8c2f4410918df6dcc99dcf23321e9a3e8e", 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.33s [INFO] running `Command { std: "docker" "inspect" "4d57899c8face10e0dfe491ef2b52e8c2f4410918df6dcc99dcf23321e9a3e8e", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "4d57899c8face10e0dfe491ef2b52e8c2f4410918df6dcc99dcf23321e9a3e8e", kill_on_drop: false }` [INFO] [stdout] 4d57899c8face10e0dfe491ef2b52e8c2f4410918df6dcc99dcf23321e9a3e8e [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc1/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=warn" "-e" "RUSTDOCFLAGS=--cap-lints=warn" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:4848fb76d95f26979359cc7e45710b1dbc8f3acb7aeedee7c460d7702230f228" "/opt/rustwide/cargo-home/bin/cargo" "+1.91.0" "test" "--frozen", kill_on_drop: false }` [INFO] [stdout] 463ba0564655214363baac75108610b2b16000c1b116f57f459a4609fc87e727 [INFO] running `Command { std: "docker" "start" "-a" "463ba0564655214363baac75108610b2b16000c1b116f57f459a4609fc87e727", kill_on_drop: false }` [INFO] [stderr] Finished `test` profile [unoptimized + debuginfo] target(s) in 0.04s [INFO] [stderr] Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/ramu_rs-b8b1481278dc09b7) [INFO] [stdout] [INFO] [stdout] running 8 tests [INFO] [stdout] test config::tests::dum_config ... ignored [INFO] [stdout] test scheduler::tests::test ... ok [INFO] [stdout] 2025-11-05T05:02:40.860631Z  INFO ramu_rs::ddr4: building ddr4 [INFO] [stdout] 2025-11-05T05:02:40.860629Z  INFO ramu_rs::ddr4: building ddr4 [INFO] [stdout] 2025-11-05T05:02:40.860646Z  INFO ramu_rs::ddr4: building ddr4 [INFO] [stdout] 2025-11-05T05:02:40.860667Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128] [INFO] [stdout] 2025-11-05T05:02:40.860669Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128] [INFO] [stdout] 2025-11-05T05:02:40.860708Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128] [INFO] [stdout] 2025-11-05T05:02:40.860711Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7] [INFO] [stdout] test utils::tests::test_addr ... ok [INFO] [stdout] 2025-11-05T05:02:40.860783Z  INFO ramu_rs::ddr4: speed_entry speed_entry=SpeedEntry { rate: 2400, freq: 1200.0, tCK: 0.8333333333333334, nBL: 4, nCCDS: 4, nCCDL: 6, nRTRS: 2, nCL: 16, nRCD: 16, nRP: 16, nCWL: 12, nRAS: 39, nRC: 55, nRTP: 9, nWTRS: 3, nWTRL: 9, nWR: 18, nRRDS: 0, nRRDL: 0, nFAW: 0, nRFC: 0, nREFI: 0, nPD: 6, nXP: 8, nXPDLL: 0, nCKESR: 7, nXS: 0, nXSDLL: 0 } [INFO] [stdout] 2025-11-05T05:02:40.860732Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7] [INFO] [stdout] 2025-11-05T05:02:40.860754Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7] [INFO] [stdout] 2025-11-05T05:02:40.860696Z  INFO ramu_rs::ddr4: building ddr4 [INFO] [stdout] 2025-11-05T05:02:40.860821Z  INFO ramu_rs::ddr4: building ddr4 [INFO] [stdout] 2025-11-05T05:02:40.860820Z  INFO ramu_rs::ddr4: speed_entry speed_entry=SpeedEntry { rate: 2400, freq: 1200.0, tCK: 0.8333333333333334, nBL: 4, nCCDS: 4, nCCDL: 6, nRTRS: 2, nCL: 16, nRCD: 16, nRP: 16, nCWL: 12, nRAS: 39, nRC: 55, nRTP: 9, nWTRS: 3, nWTRL: 9, nWR: 18, nRRDS: 0, nRRDL: 0, nFAW: 0, nRFC: 0, nREFI: 0, nPD: 6, nXP: 8, nXPDLL: 0, nCKESR: 7, nXS: 0, nXSDLL: 0 } [INFO] [stdout] 2025-11-05T05:02:40.860829Z  INFO ramu_rs::ddr4: speed_entry speed_entry=SpeedEntry { rate: 2400, freq: 1200.0, tCK: 0.8333333333333334, nBL: 4, nCCDS: 4, nCCDL: 6, nRTRS: 2, nCL: 16, nRCD: 16, nRP: 16, nCWL: 12, nRAS: 39, nRC: 55, nRTP: 9, nWTRS: 3, nWTRL: 9, nWR: 18, nRRDS: 0, nRRDL: 0, nFAW: 0, nRFC: 0, nREFI: 0, nPD: 6, nXP: 8, nXPDLL: 0, nCKESR: 7, nXS: 0, nXSDLL: 0 } [INFO] [stdout] 2025-11-05T05:02:40.860834Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128] [INFO] [stdout] 2025-11-05T05:02:40.860843Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128] [INFO] [stdout] 2025-11-05T05:02:40.860851Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7] [INFO] [stdout] 2025-11-05T05:02:40.860864Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.860868Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.860875Z  INFO ramu_rs::ddr4: speed_entry speed_entry=SpeedEntry { rate: 2400, freq: 1200.0, tCK: 0.8333333333333334, nBL: 4, nCCDS: 4, nCCDL: 6, nRTRS: 2, nCL: 16, nRCD: 16, nRP: 16, nCWL: 12, nRAS: 39, nRC: 55, nRTP: 9, nWTRS: 3, nWTRL: 9, nWR: 18, nRRDS: 0, nRRDL: 0, nFAW: 0, nRFC: 0, nREFI: 0, nPD: 6, nXP: 8, nXPDLL: 0, nCKESR: 7, nXS: 0, nXSDLL: 0 } [INFO] [stdout] 2025-11-05T05:02:40.860879Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.860855Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7] [INFO] [stdout] 2025-11-05T05:02:40.860883Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.860891Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.860895Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.860850Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.860902Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.860907Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.860909Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.860915Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.860899Z  INFO ramu_rs::ddr4: speed_entry speed_entry=SpeedEntry { rate: 2400, freq: 1200.0, tCK: 0.8333333333333334, nBL: 4, nCCDS: 4, nCCDL: 6, nRTRS: 2, nCL: 16, nRCD: 16, nRP: 16, nCWL: 12, nRAS: 39, nRC: 55, nRTP: 9, nWTRS: 3, nWTRL: 9, nWR: 18, nRRDS: 0, nRRDL: 0, nFAW: 0, nRFC: 0, nREFI: 0, nPD: 6, nXP: 8, nXPDLL: 0, nCKESR: 7, nXS: 0, nXSDLL: 0 } [INFO] [stdout] 2025-11-05T05:02:40.860919Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.860922Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.860928Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.860932Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.860925Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.860935Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.860939Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.860945Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.860946Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.860968Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.860948Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861016Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.860950Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861033Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861042Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861045Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.860948Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861057Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861059Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861069Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861071Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.860995Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861079Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861080Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861077Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861090Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861090Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: ACT, dist: 4, val: 0, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 39, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.860995Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861100Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861098Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861103Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PRE timing_command=[TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861112Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861113Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861116Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PREA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861109Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861122Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: ACT, dist: 4, val: 0, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 39, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861126Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861130Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861128Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 9, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861134Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PRE timing_command=[TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861137Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861143Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861114Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861146Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PREA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861148Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861157Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861157Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 9, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861145Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 34, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 34, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861238Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 34, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 34, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861169Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861255Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861261Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861271Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 35, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 50, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861284Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=REF timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861283Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 35, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 50, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861210Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861296Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDE timing_command=[TimeEntry { cmd: PDX, dist: 1, val: 6, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861299Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=REF timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861307Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDX timing_command=[TimeEntry { cmd: RD, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 8, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861278Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861328Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRE timing_command=[TimeEntry { cmd: SRX, dist: 1, val: 7, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861311Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDE timing_command=[TimeEntry { cmd: PDX, dist: 1, val: 6, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861340Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRX timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 0, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861340Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861351Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861355Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861355Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDX timing_command=[TimeEntry { cmd: RD, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 8, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861363Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861366Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861374Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861389Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861401Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861378Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861416Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861423Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: ACT, dist: 4, val: 0, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 39, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861443Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRE timing_command=[TimeEntry { cmd: SRX, dist: 1, val: 7, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861449Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PRE timing_command=[TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861155Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: ACT, dist: 4, val: 0, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 39, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861479Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRX timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 0, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861307Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861497Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PREA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861502Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861515Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861514Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 9, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861529Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861428Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861511Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861539Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 34, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 34, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861549Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861559Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861540Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861566Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861570Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: ACT, dist: 4, val: 0, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 39, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861575Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861557Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861597Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861593Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PRE timing_command=[TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861604Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 35, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 50, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861619Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861578Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861623Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PREA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861632Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861637Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 9, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861643Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861648Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861657Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861621Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=REF timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861659Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861689Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDE timing_command=[TimeEntry { cmd: PDX, dist: 1, val: 6, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861696Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861677Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=ACT timing_command=[TimeEntry { cmd: RD, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 39, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861708Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861713Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PRE timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861654Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 34, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 34, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861726Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861728Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=ACT timing_command=[TimeEntry { cmd: RD, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 39, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861743Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RD timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 9, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861729Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861763Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WR timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 34, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861745Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PRE timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861773Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RDA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861777Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861774Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 35, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 50, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861787Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WRA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 50, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861789Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RD timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 9, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861791Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=REF timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861798Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861801Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WR timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 34, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861804Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDE timing_command=[TimeEntry { cmd: PDX, dist: 1, val: 6, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861809Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861812Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RDA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861819Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861830Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WRA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 50, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861841Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861815Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDX timing_command=[TimeEntry { cmd: RD, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 8, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861843Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861705Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDX timing_command=[TimeEntry { cmd: RD, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 8, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861902Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861911Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRE timing_command=[TimeEntry { cmd: SRX, dist: 1, val: 7, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861876Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRE timing_command=[TimeEntry { cmd: SRX, dist: 1, val: 7, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861925Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRX timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 0, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861938Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861949Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861915Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861963Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861970Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861974Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.861986Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861892Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.862009Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.862013Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.862093Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861987Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.862056Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRX timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 0, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.862111Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.862150Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.862176Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.862143Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.862191Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.862193Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.862205Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.862218Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.862236Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.862241Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.862252Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.862257Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.862263Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.862268Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.862275Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.862342Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.862399Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.862434Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.862278Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.861582Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PRE timing_command=[TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.862578Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PREA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.862605Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 9, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.862622Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 34, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 34, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.862640Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.862656Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 35, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 50, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.862677Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=REF timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.862690Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDE timing_command=[TimeEntry { cmd: PDX, dist: 1, val: 6, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.862701Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDX timing_command=[TimeEntry { cmd: RD, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 8, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.862721Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRE timing_command=[TimeEntry { cmd: SRX, dist: 1, val: 7, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.862734Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRX timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 0, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.862747Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.862771Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.862783Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.862797Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.862809Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.862821Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.862832Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.862845Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.862856Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.862866Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.862877Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.862887Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.862899Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=ACT timing_command=[TimeEntry { cmd: RD, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 39, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.862915Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PRE timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.862203Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.862927Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.862169Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.862516Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863023Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.862536Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863044Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863044Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=ACT timing_command=[TimeEntry { cmd: RD, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 39, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.863053Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863068Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863060Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863065Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PRE timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.863085Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863087Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863089Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.862954Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863099Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RD timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 9, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.863110Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WR timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 34, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.863115Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.862988Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RD timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 9, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.863121Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RDA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.863128Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863139Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WR timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 34, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.863154Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RDA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.863157Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863166Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WRA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 50, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.863168Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863177Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863178Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863189Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863198Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863188Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863209Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863219Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863216Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863134Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WRA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 50, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.863230Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863235Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863241Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863096Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863098Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863263Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863268Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863270Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863274Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863280Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863284Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863290Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863295Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863301Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863306Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863245Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863311Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863316Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863321Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863323Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863326Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863332Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863334Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863337Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863342Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863344Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863354Z  INFO ramu_rs::ddr4: read_latency read_latency=20 [INFO] [stdout] 2025-11-05T05:02:40.863355Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863356Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863365Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863367Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863378Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863389Z  INFO ramu_rs::ddr4: read_latency read_latency=20 [INFO] [stdout] 2025-11-05T05:02:40.863282Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=ACT timing_command=[TimeEntry { cmd: RD, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 39, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.863414Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PRE timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.863425Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863435Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RD timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 9, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.863446Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WR timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 34, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.863375Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863502Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863502Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: addr=1 [INFO] [stdout] 2025-11-05T05:02:40.863246Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863595Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863630Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863668Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863630Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863461Z DEBUG ramu_rs::test: addr_1=0 addr_2=8192 [INFO] [stdout] 2025-11-05T05:02:40.863748Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863752Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.863755Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863762Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863768Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863770Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.863772Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863778Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863783Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863786Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=1 [INFO] [stdout] 2025-11-05T05:02:40.863789Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863457Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RDA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.863818Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863823Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WRA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 50, sibling: false }] [INFO] [stdout] 2025-11-05T05:02:40.863832Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863667Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: [0, 0, 0, 0, 0, 0] [INFO] [stdout] 2025-11-05T05:02:40.863856Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863793Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863867Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863878Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863837Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863881Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863889Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863893Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863899Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863893Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863906Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863909Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863915Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863918Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863920Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863925Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863929Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863930Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863935Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863940Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863941Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863946Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863951Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863954Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863956Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863962Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863964Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863966Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863973Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863975Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863982Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863986Z  INFO ramu_rs::ddr4: read_latency read_latency=20 [INFO] [stdout] 2025-11-05T05:02:40.863984Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863993Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.863996Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.864004Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.864006Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.864015Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.864017Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.864025Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.864028Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.864035Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.864039Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.864046Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.864052Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.864056Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.864063Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.864067Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.864073Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.864077Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.864084Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.864088Z  INFO ramu_rs::ddr4: read_latency read_latency=20 [INFO] [stdout] 2025-11-05T05:02:40.864095Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.864107Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.864118Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.864148Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.864172Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.864087Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.864198Z DEBUG ramu_rs::test: addr_1=0 addr_2=8192 [INFO] [stdout] 2025-11-05T05:02:40.864198Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.864213Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.864212Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.864222Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.864234Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=1 [INFO] [stdout] 2025-11-05T05:02:40.864210Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.864242Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.864245Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.864253Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=0 [INFO] [stdout] 2025-11-05T05:02:40.864254Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.864256Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.864262Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.864266Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[] [INFO] [stdout] 2025-11-05T05:02:40.864267Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.864273Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.864277Z  INFO ramu_rs::ddr4: read_latency read_latency=20 [INFO] [stdout] 2025-11-05T05:02:40.864278Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.864284Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.864292Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.864295Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.864305Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.864303Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=0 future=1 [INFO] [stdout] 2025-11-05T05:02:40.864314Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=0 future=0 [INFO] [stdout] 2025-11-05T05:02:40.864317Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=0 future=40 [INFO] [stdout] 2025-11-05T05:02:40.864327Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=0 future=39 [INFO] [stdout] 2025-11-05T05:02:40.864329Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=0 future=56 [INFO] [stdout] 2025-11-05T05:02:40.864340Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=0 future=55 [INFO] [stdout] 2025-11-05T05:02:40.864343Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=0 future=2 [INFO] [stdout] 2025-11-05T05:02:40.864352Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=0 future=1 [INFO] [stdout] 2025-11-05T05:02:40.864356Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=0 future=1 [INFO] [stdout] 2025-11-05T05:02:40.863799Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.864366Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=0 future=0 [INFO] [stdout] 2025-11-05T05:02:40.864379Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=0 future=16 [INFO] [stdout] 2025-11-05T05:02:40.864389Z DEBUG ramu_rs::test: addr_1=0 addr_2=8192 [INFO] [stdout] 2025-11-05T05:02:40.864385Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.864392Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=0 future=16 [INFO] [stdout] 2025-11-05T05:02:40.864405Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.864404Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.864406Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=0 future=16 [INFO] [stdout] 2025-11-05T05:02:40.864415Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.864416Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.863866Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: 0 [INFO] [stdout] 2025-11-05T05:02:40.864444Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.864455Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=0 future=1 [INFO] [stdout] 2025-11-05T05:02:40.864369Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=0 future=17 [INFO] [stdout] 2025-11-05T05:02:40.864456Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: addr=65 [INFO] [stdout] 2025-11-05T05:02:40.864495Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=0 future=40 [INFO] [stdout] 2025-11-05T05:02:40.864496Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=0 future=17 [INFO] [stdout] 2025-11-05T05:02:40.864509Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=0 future=56 [INFO] [stdout] 2025-11-05T05:02:40.864513Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=0 future=17 [INFO] [stdout] 2025-11-05T05:02:40.864509Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: [0, 0, 0, 0, 0, 1] [INFO] [stdout] 2025-11-05T05:02:40.864523Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=0 future=2 [INFO] [stdout] 2025-11-05T05:02:40.864526Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=0 future=17 [INFO] [stdout] 2025-11-05T05:02:40.864531Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: 64 [INFO] [stdout] 2025-11-05T05:02:40.864536Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=0 future=1 [INFO] [stdout] 2025-11-05T05:02:40.864539Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=0 future=56 [INFO] [stdout] 2025-11-05T05:02:40.864548Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=0 future=17 [INFO] [stdout] 2025-11-05T05:02:40.864552Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=0 future=40 [INFO] [stdout] 2025-11-05T05:02:40.864427Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=1 [INFO] [stdout] 2025-11-05T05:02:40.864419Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=0 future=16 [INFO] [stdout] 2025-11-05T05:02:40.864548Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: addr=257 [INFO] [stdout] 2025-11-05T05:02:40.864580Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.864595Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.864565Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=0 future=17 [INFO] [stdout] 2025-11-05T05:02:40.864594Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: [0, 0, 0, 0, 0, 4] [INFO] [stdout] 2025-11-05T05:02:40.864606Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.864608Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=0 future=17 [INFO] [stdout] 2025-11-05T05:02:40.864616Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.864664Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=0 future=17 [INFO] [stdout] 2025-11-05T05:02:40.864616Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: 256 [INFO] [stdout] 2025-11-05T05:02:40.864673Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.864678Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=0 future=56 [INFO] [stdout] 2025-11-05T05:02:40.864685Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.864587Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=0 future=55 [INFO] [stdout] 2025-11-05T05:02:40.864690Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=0 future=40 [INFO] [stdout] 2025-11-05T05:02:40.864696Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.864708Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.864716Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.864724Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.864729Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.864733Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.864741Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.864758Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.864707Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=0 future=39 [INFO] [stdout] 2025-11-05T05:02:40.864740Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.864768Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.864775Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.864780Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.864789Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.864798Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.864636Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.864820Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.864820Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.864805Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.864831Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.864832Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.864837Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.864841Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.864842Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.864847Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.864849Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.864853Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.864854Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.864858Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.864863Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.864862Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=0 future=1 [INFO] [stdout] 2025-11-05T05:02:40.864868Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.864871Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.864880Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.864875Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=0 future=40 [INFO] [stdout] 2025-11-05T05:02:40.864888Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.864890Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=0 future=56 [INFO] [stdout] 2025-11-05T05:02:40.864896Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.864878Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.864904Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.864903Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=0 future=2 [INFO] [stdout] 2025-11-05T05:02:40.864910Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.864912Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.864921Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.864921Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.864929Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.864935Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.864939Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.864944Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.864949Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.864952Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.864957Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.864780Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.864960Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.864985Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.864990Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.864997Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.865000Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.864998Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.865008Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.865008Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.865010Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.865017Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.865016Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.865018Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.865026Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.865026Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.865027Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.865034Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.865036Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.865037Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.865042Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.865044Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.865045Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.865051Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.865053Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.865054Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.865058Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.865062Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.865066Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.865071Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.865077Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.865080Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.865085Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.865086Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.865090Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.865093Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.865095Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.865098Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.865101Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.865104Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.865107Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.865109Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.865113Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.865117Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.865118Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.865121Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.865125Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.865127Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.865130Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.865134Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.865135Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.865140Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.865143Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.865144Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.865153Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.865151Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.865160Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.865161Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.865169Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.865148Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.865172Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.865178Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.865179Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.865180Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.865186Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.865189Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.865189Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.865194Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.865197Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.865198Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.865203Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.865206Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.865207Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.865210Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.865216Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.865216Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.865218Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.865224Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.865227Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.865230Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.865235Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.865239Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.865243Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.865248Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.865251Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.865233Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.865258Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.865261Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.865264Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.865267Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.865269Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.865272Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.865276Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.865278Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.865281Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.865285Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.865286Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.865291Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.865293Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.865294Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.865299Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.865302Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.865303Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.865308Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.865311Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.865312Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.865318Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.865320Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] test ddr4::tests::test_address ... ok [INFO] [stdout] 2025-11-05T05:02:40.865329Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.865328Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.865337Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.865318Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.865339Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.865345Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.865347Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.865350Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.865354Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.865356Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.865359Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.865361Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.865366Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.865368Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.865370Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.865374Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.865376Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.865379Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.865383Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.865384Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.865386Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.865393Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.865394Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.865395Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.865402Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.865403Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.865411Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.865412Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.865421Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.865401Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.865430Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.865437Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.865436Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.865446Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.864916Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=0 future=1 [INFO] [stdout] 2025-11-05T05:02:40.865451Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.865422Z DEBUG ramu_rs::controller: issue cmd cmd=RD clk=16 [INFO] [stdout] 2025-11-05T05:02:40.865487Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=0 future=17 [INFO] [stdout] 2025-11-05T05:02:40.865455Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.865520Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.865571Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=0 future=17 [INFO] [stdout] 2025-11-05T05:02:40.865583Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.865549Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.865593Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.865592Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.865597Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.865603Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.865605Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.865611Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.865609Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.865613Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.865619Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.865622Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.865621Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.865617Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=0 future=17 [INFO] [stdout] 2025-11-05T05:02:40.865628Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.865631Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.865636Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.865633Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RD current=0 future=20 [INFO] [stdout] 2025-11-05T05:02:40.865635Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=0 future=17 [INFO] [stdout] 2025-11-05T05:02:40.865639Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.865644Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.865646Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RDA current=0 future=20 [INFO] [stdout] 2025-11-05T05:02:40.865689Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RD current=0 future=20 [INFO] [stdout] 2025-11-05T05:02:40.865708Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RDA current=0 future=20 [INFO] [stdout] 2025-11-05T05:02:40.865722Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WR current=0 future=26 [INFO] [stdout] 2025-11-05T05:02:40.865650Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.865776Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.865787Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.865648Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=0 future=56 [INFO] [stdout] 2025-11-05T05:02:40.865798Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.865810Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.865818Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.865653Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.865815Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=0 future=40 [INFO] [stdout] 2025-11-05T05:02:40.865834Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.865838Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.865846Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.865848Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.865738Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WRA current=0 future=26 [INFO] [stdout] 2025-11-05T05:02:40.865856Z DEBUG ramu_rs::controller: issue cmd cmd=RD clk=17 [INFO] [stdout] 2025-11-05T05:02:40.865858Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.865861Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PREA current=39 future=25 [INFO] [stdout] 2025-11-05T05:02:40.865864Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.865868Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.865876Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.865878Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.865875Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PDE current=1 future=37 [INFO] [stdout] 2025-11-05T05:02:40.865886Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.865887Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.865890Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RD current=0 future=22 [INFO] [stdout] 2025-11-05T05:02:40.865896Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.865899Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.865904Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RDA current=0 future=22 [INFO] [stdout] 2025-11-05T05:02:40.865952Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=RD timing.cmd=PRE current=39 future=25 [INFO] [stdout] 2025-11-05T05:02:40.865978Z DEBUG ramu_rs::controller: read request finished req=Request { addr: 0, addr_vec: [0, 0, 0, 0, 0, 0], done_setup: true, req_type: Read, arrival_time: 0, finish_time: 36 } clk=16 req.finish_time=36 [INFO] [stdout] 2025-11-05T05:02:40.865907Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RD current=0 future=21 [INFO] [stdout] 2025-11-05T05:02:40.866070Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RDA current=0 future=21 [INFO] [stdout] 2025-11-05T05:02:40.866094Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RD current=0 future=21 [INFO] [stdout] 2025-11-05T05:02:40.866125Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RDA current=0 future=21 [INFO] [stdout] 2025-11-05T05:02:40.866140Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WR current=0 future=27 [INFO] [stdout] 2025-11-05T05:02:40.866156Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WRA current=0 future=27 [INFO] [stdout] 2025-11-05T05:02:40.866172Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PREA current=40 future=26 [INFO] [stdout] 2025-11-05T05:02:40.866188Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PDE current=2 future=38 [INFO] [stdout] 2025-11-05T05:02:40.866207Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RD current=0 future=23 [INFO] [stdout] 2025-11-05T05:02:40.866231Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RDA current=0 future=23 [INFO] [stdout] 2025-11-05T05:02:40.865908Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.866295Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.866310Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.865827Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.866345Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.866363Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.866320Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.866373Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.866380Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.866249Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=RD timing.cmd=PRE current=40 future=26 [INFO] [stdout] 2025-11-05T05:02:40.866482Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.866423Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.866498Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.866506Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.866509Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.866500Z DEBUG ramu_rs::controller: read request finished req=Request { addr: 0, addr_vec: [0, 0, 0, 0, 0, 0], done_setup: true, req_type: Read, arrival_time: 0, finish_time: 37 } clk=17 req.finish_time=37 [INFO] [stdout] 2025-11-05T05:02:40.866517Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.866523Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.866531Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.866539Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.866549Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.866521Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.866553Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.866556Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.866559Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.866563Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.866564Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.866570Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.866574Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.866572Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.866581Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.866581Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.866584Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.866590Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.866592Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.866589Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.866599Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.866608Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.866625Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.866626Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.866634Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.866636Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.866636Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.866644Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.866645Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.866651Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.866683Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.866699Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.866711Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.866723Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.866651Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.866656Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.866772Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.866783Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.866733Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.866786Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.866807Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.866871Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.866880Z DEBUG ramu_rs::controller: issue cmd cmd=RD clk=17 [INFO] [stdout] 2025-11-05T05:02:40.866887Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.866899Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.866890Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.866910Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.866936Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.866937Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.866947Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.866951Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.866960Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.866963Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.866973Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.866984Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.866996Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.866973Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RD current=0 future=21 [INFO] [stdout] 2025-11-05T05:02:40.867005Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.867015Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.867011Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RDA current=0 future=21 [INFO] [stdout] 2025-11-05T05:02:40.867037Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.867050Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.867050Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RD current=0 future=21 [INFO] [stdout] 2025-11-05T05:02:40.867072Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.867081Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.867079Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RDA current=0 future=21 [INFO] [stdout] 2025-11-05T05:02:40.867094Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.867105Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.867096Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WR current=0 future=27 [INFO] [stdout] 2025-11-05T05:02:40.867116Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.867125Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.867123Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WRA current=0 future=27 [INFO] [stdout] 2025-11-05T05:02:40.867147Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.867156Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.867166Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.867179Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.867188Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.867200Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.867211Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.867231Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.867243Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.867254Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.867249Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PREA current=40 future=26 [INFO] [stdout] 2025-11-05T05:02:40.867267Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.867270Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PDE current=2 future=38 [INFO] [stdout] 2025-11-05T05:02:40.867306Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RD current=0 future=23 [INFO] [stdout] 2025-11-05T05:02:40.867324Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RDA current=0 future=23 [INFO] [stdout] 2025-11-05T05:02:40.867329Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.867337Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=RD timing.cmd=PRE current=40 future=26 [INFO] [stdout] 2025-11-05T05:02:40.867342Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.867351Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.867351Z DEBUG ramu_rs::controller: read request finished req=Request { addr: 0, addr_vec: [0, 0, 0, 0, 0, 0], done_setup: true, req_type: Read, arrival_time: 0, finish_time: 37 } clk=17 req.finish_time=37 [INFO] [stdout] 2025-11-05T05:02:40.867363Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.867365Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.867373Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.867382Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.867391Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.867399Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.867371Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.867408Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.867419Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.867418Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.867427Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.867431Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.867436Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.867440Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.867446Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.867454Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.867481Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.867493Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.867449Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.867501Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.867510Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.867511Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.867520Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.867521Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.867527Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.867536Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.867546Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.867555Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.867564Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.867574Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.867531Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.867582Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.867588Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.867591Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.867598Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.867601Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.867609Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.867610Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.867619Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.867619Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.867630Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.867638Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.867647Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.867657Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.867664Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.867629Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.867673Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.867679Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.867686Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.867691Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.867694Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.867699Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.867703Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.867709Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.867713Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.867720Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.867768Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.867781Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.867795Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.867804Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.867721Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.867856Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.867896Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.867930Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.867277Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.867944Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.867951Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.867973Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.867954Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.868024Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.868037Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.868039Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.868049Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.868050Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.868059Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.868080Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.868061Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.868109Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.867985Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.868121Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.868128Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.868131Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.868139Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.868140Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.868148Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.868150Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.868159Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.868168Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.868245Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.868160Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.868264Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.868277Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.868321Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.868332Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.868335Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.868345Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.868356Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.868393Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.868354Z DEBUG ramu_rs::test: recv req=Request { addr: 0, addr_vec: [0, 0, 0, 0, 0, 0], done_setup: true, req_type: Read, arrival_time: 0, finish_time: 37 } [INFO] [stdout] 2025-11-05T05:02:40.868420Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.868089Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.868439Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.868451Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.868549Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.868601Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.868616Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.868627Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.868641Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.868645Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.868681Z DEBUG ramu_rs::test: recv req=Request { addr: 0, addr_vec: [0, 0, 0, 0, 0, 0], done_setup: true, req_type: Read, arrival_time: 0, finish_time: 37 } [INFO] [stdout] 2025-11-05T05:02:40.868691Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.868696Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.868703Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.868706Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.868717Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.868718Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.868727Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.868729Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.868649Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.868792Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.868797Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.868804Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.868823Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.868829Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.868832Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.868841Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.868842Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.868851Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.868882Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.868904Z DEBUG ramu_rs::controller: issue cmd cmd=PRE clk=40 [INFO] [stdout] 2025-11-05T05:02:40.868921Z DEBUG ramu_rs::controller: issue cmd cmd=PRE clk=40 [INFO] [stdout] 2025-11-05T05:02:40.868977Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.868993Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.868993Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.869008Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.869021Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.869033Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.869046Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2025-11-05T05:02:40.868941Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.869059Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=REF current=56 future=56 [INFO] [stdout] 2025-11-05T05:02:40.869063Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.869077Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.869075Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=SRE current=0 future=56 [INFO] [stdout] 2025-11-05T05:02:40.869098Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.869108Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.869122Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=PRE timing.cmd=ACT current=56 future=56 [INFO] [stdout] 2025-11-05T05:02:40.869025Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2025-11-05T05:02:40.869182Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.869205Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.869219Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.869228Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.869159Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.869241Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.869247Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.869250Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.869271Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.869283Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.869296Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.869306Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.869320Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.869203Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=REF current=56 future=56 [INFO] [stdout] 2025-11-05T05:02:40.869329Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.869348Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=SRE current=0 future=56 [INFO] [stdout] 2025-11-05T05:02:40.869354Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.869367Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=PRE timing.cmd=ACT current=56 future=56 [INFO] [stdout] 2025-11-05T05:02:40.869376Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.869388Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.869396Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.869408Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.869297Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.869416Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.869420Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.869429Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.869432Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.869437Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.869443Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.869447Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.869451Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.869455Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.869511Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.869554Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.869589Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.869603Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.869609Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.869616Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.869619Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.869629Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.869631Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.869639Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.869640Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.869651Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.869653Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.869662Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.869676Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.869661Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.869686Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.869692Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.869535Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.869716Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.869697Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.869735Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.869757Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.869768Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.869766Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.869780Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.869792Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.869805Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.869815Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.869825Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.869809Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.869885Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.869899Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.869891Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=56 [INFO] [stdout] 2025-11-05T05:02:40.869911Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.869915Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.869923Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.869938Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.869948Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.869960Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.869970Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.869979Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.869993Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.870002Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.870016Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.869926Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.869870Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.870044Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.870046Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.870055Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.870059Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2025-11-05T05:02:40.870064Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-11-05T05:02:40.870070Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.870074Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.870080Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=1 future=56 [INFO] [stdout] 2025-11-05T05:02:40.870085Z DEBUG ramu_rs::controller: issue cmd cmd=WR clk=17 [INFO] [stdout] 2025-11-05T05:02:40.870093Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=40 future=95 [INFO] [stdout] 2025-11-05T05:02:40.870095Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.870106Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=56 future=111 [INFO] [stdout] 2025-11-05T05:02:40.870107Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.870121Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.870119Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=38 future=57 [INFO] [stdout] 2025-11-05T05:02:40.870145Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.870160Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WR current=0 future=21 [INFO] [stdout] 2025-11-05T05:02:40.870168Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=1 future=56 [INFO] [stdout] 2025-11-05T05:02:40.870178Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WRA current=0 future=21 [INFO] [stdout] 2025-11-05T05:02:40.870184Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=17 future=72 [INFO] [stdout] 2025-11-05T05:02:40.870192Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WR current=0 future=21 [INFO] [stdout] 2025-11-05T05:02:40.870197Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=17 future=72 [INFO] [stdout] 2025-11-05T05:02:40.870212Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=17 future=72 [INFO] [stdout] 2025-11-05T05:02:40.870211Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WRA current=0 future=21 [INFO] [stdout] 2025-11-05T05:02:40.870234Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RD current=0 future=36 [INFO] [stdout] 2025-11-05T05:02:40.870251Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RDA current=0 future=36 [INFO] [stdout] 2025-11-05T05:02:40.870264Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PREA current=40 future=51 [INFO] [stdout] 2025-11-05T05:02:40.870231Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=17 future=72 [INFO] [stdout] 2025-11-05T05:02:40.870024Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.870318Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=56 future=111 [INFO] [stdout] 2025-11-05T05:02:40.870372Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.870379Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=40 future=95 [INFO] [stdout] 2025-11-05T05:02:40.870386Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.870397Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.870397Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.870406Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.870407Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.870416Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.870417Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.870425Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.870428Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.870437Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.870437Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.870446Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.870446Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.870457Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=56 [INFO] [stdout] 2025-11-05T05:02:40.870458Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.870491Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.870489Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.870501Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.870504Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.870512Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.870515Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.870520Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.870528Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.870527Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2025-11-05T05:02:40.870538Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.870539Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.870545Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.870549Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=1 future=56 [INFO] [stdout] 2025-11-05T05:02:40.870554Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.870563Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.870562Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=40 future=95 [INFO] [stdout] 2025-11-05T05:02:40.870571Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.870576Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=56 future=111 [INFO] [stdout] 2025-11-05T05:02:40.870581Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.870592Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.870590Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=38 future=57 [INFO] [stdout] 2025-11-05T05:02:40.870599Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.870608Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.870605Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=1 future=56 [INFO] [stdout] 2025-11-05T05:02:40.870618Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.870620Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=17 future=72 [INFO] [stdout] 2025-11-05T05:02:40.870626Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.870635Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.870302Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PDE current=2 future=51 [INFO] [stdout] 2025-11-05T05:02:40.870660Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.870662Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WR current=0 future=23 [INFO] [stdout] 2025-11-05T05:02:40.870669Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.870678Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.870676Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WRA current=0 future=23 [INFO] [stdout] 2025-11-05T05:02:40.870688Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.870689Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RD current=0 future=42 [INFO] [stdout] 2025-11-05T05:02:40.870696Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.870705Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.870634Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=17 future=72 [INFO] [stdout] 2025-11-05T05:02:40.870702Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RDA current=0 future=42 [INFO] [stdout] 2025-11-05T05:02:40.870728Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.870739Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.870737Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=WR timing.cmd=PRE current=40 future=51 [INFO] [stdout] 2025-11-05T05:02:40.870748Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.870758Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.870762Z DEBUG ramu_rs::controller: write request finished req=Request { addr: 0, addr_vec: [0, 0, 0, 0, 0, 0], done_setup: true, req_type: Write, arrival_time: 0, finish_time: 17 } [INFO] [stdout] 2025-11-05T05:02:40.870766Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.870775Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.870778Z DEBUG ramu_rs::test: recv req=Request { addr: 0, addr_vec: [0, 0, 0, 0, 0, 0], done_setup: true, req_type: Write, arrival_time: 0, finish_time: 17 } [INFO] [stdout] 2025-11-05T05:02:40.870785Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.870789Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.870793Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.870798Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.870803Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.870807Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.870813Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.870818Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.870820Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.870827Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.870829Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.870836Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.870838Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.870847Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.870847Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.870857Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.870858Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.870866Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.870868Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-11-05T05:02:40.870877Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.870877Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.870886Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.870887Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-11-05T05:02:40.870895Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.870898Z DEBUG ramu_rs::controller: issue cmd cmd=RD clk=72 [INFO] [stdout] 2025-11-05T05:02:40.870905Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.870907Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.870914Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.870917Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.870923Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.870929Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.870933Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.870939Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2025-11-05T05:02:40.870941Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.870951Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.870951Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RD current=21 future=76 [INFO] [stdout] 2025-11-05T05:02:40.870961Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.870963Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RDA current=21 future=76 [INFO] [stdout] 2025-11-05T05:02:40.870987Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=17 future=72 [INFO] [stdout] 2025-11-05T05:02:40.870990Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RD current=21 future=76 [INFO] [stdout] 2025-11-05T05:02:40.871004Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=17 future=72 [INFO] [stdout] 2025-11-05T05:02:40.871004Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RDA current=21 future=76 [INFO] [stdout] 2025-11-05T05:02:40.871017Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=56 future=111 [INFO] [stdout] 2025-11-05T05:02:40.871018Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WR current=27 future=82 [INFO] [stdout] 2025-11-05T05:02:40.871030Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=40 future=95 [INFO] [stdout] 2025-11-05T05:02:40.871032Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WRA current=27 future=82 [INFO] [stdout] 2025-11-05T05:02:40.871046Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.871045Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PREA current=95 future=81 [INFO] [stdout] 2025-11-05T05:02:40.871054Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.871058Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PDE current=57 future=93 [INFO] [stdout] 2025-11-05T05:02:40.871064Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.871074Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.871072Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RD current=23 future=78 [INFO] [stdout] 2025-11-05T05:02:40.871083Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.871084Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RDA current=23 future=78 [INFO] [stdout] 2025-11-05T05:02:40.871092Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.871096Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=RD timing.cmd=PRE current=95 future=81 [INFO] [stdout] 2025-11-05T05:02:40.871102Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.871111Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.871110Z DEBUG ramu_rs::controller: read request finished req=Request { addr: 8192, addr_vec: [0, 0, 0, 0, 1, 0], done_setup: true, req_type: Read, arrival_time: 0, finish_time: 92 } clk=72 req.finish_time=92 [INFO] [stdout] 2025-11-05T05:02:40.871123Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.871128Z DEBUG ramu_rs::test: recv req=Request { addr: 8192, addr_vec: [0, 0, 0, 0, 1, 0], done_setup: true, req_type: Read, arrival_time: 0, finish_time: 92 } [INFO] [stdout] 2025-11-05T05:02:40.871133Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.871141Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.871151Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.871161Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.871170Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.871179Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.871189Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.871197Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.871206Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.871217Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.871233Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.871243Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.871253Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.871262Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.871271Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.871281Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.871297Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.871308Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] test test::test_memory_diffrent_row ... ok [INFO] [stdout] 2025-11-05T05:02:40.871318Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.871327Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.871336Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.871346Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.871354Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.871365Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.871375Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.871384Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.871393Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.871403Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.871412Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.871421Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.871432Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.871441Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.871450Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.871461Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.870970Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.871494Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.871519Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.871532Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.871540Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.871545Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.871549Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.871553Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.871559Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.871563Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.871569Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.871574Z DEBUG ramu_rs::controller: issue cmd cmd=WR clk=72 [INFO] [stdout] 2025-11-05T05:02:40.871577Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.871586Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.871584Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.871596Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.871597Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.871606Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.871608Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.871616Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.871624Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2025-11-05T05:02:40.871627Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.871636Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.871663Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.871635Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WR current=0 future=76 [INFO] [stdout] 2025-11-05T05:02:40.871676Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.871684Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.871682Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WRA current=0 future=76 [INFO] [stdout] 2025-11-05T05:02:40.871694Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.871700Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WR current=27 future=76 [INFO] [stdout] 2025-11-05T05:02:40.871711Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.871713Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WRA current=27 future=76 [INFO] [stdout] 2025-11-05T05:02:40.871719Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.871727Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.871725Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RD current=21 future=91 [INFO] [stdout] 2025-11-05T05:02:40.871737Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.871738Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RDA current=21 future=91 [INFO] [stdout] 2025-11-05T05:02:40.871749Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.871751Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PREA current=95 future=106 [INFO] [stdout] 2025-11-05T05:02:40.871757Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.871767Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.871763Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PDE current=57 future=106 [INFO] [stdout] 2025-11-05T05:02:40.871777Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.871779Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WR current=0 future=78 [INFO] [stdout] 2025-11-05T05:02:40.871812Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WRA current=0 future=78 [INFO] [stdout] 2025-11-05T05:02:40.871786Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.871831Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RD current=23 future=97 [INFO] [stdout] 2025-11-05T05:02:40.871836Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.871846Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.871866Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.871845Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RDA current=23 future=97 [INFO] [stdout] 2025-11-05T05:02:40.871880Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.871889Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.871885Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=WR timing.cmd=PRE current=95 future=106 [INFO] [stdout] 2025-11-05T05:02:40.871899Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.871903Z DEBUG ramu_rs::controller: write request finished req=Request { addr: 8192, addr_vec: [0, 0, 0, 0, 1, 0], done_setup: true, req_type: Write, arrival_time: 0, finish_time: 72 } [INFO] [stdout] 2025-11-05T05:02:40.871926Z DEBUG ramu_rs::test: recv req=Request { addr: 8192, addr_vec: [0, 0, 0, 0, 1, 0], done_setup: true, req_type: Write, arrival_time: 0, finish_time: 72 } [INFO] [stdout] 2025-11-05T05:02:40.871908Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.871943Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.871955Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.871966Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.871978Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.871987Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.871998Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.872007Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.872019Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.872031Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.872040Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.872051Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.872062Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.872074Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.872084Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.872095Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.872115Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] test test::test_memory_read_and_write ... ok2025-11-05T05:02:40.872126Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.872146Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.872157Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.872165Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.872178Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.872187Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.872195Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.872209Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.872224Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.872235Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.872244Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.872252Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.872264Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.872273Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.872284Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.872292Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.872306Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.872313Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.872322Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.872331Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.872347Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.872356Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.872366Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.872374Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.872418Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.872431Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.872439Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.872448Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] [INFO] [stdout] 2025-11-05T05:02:40.872485Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.872495Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.872503Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.872516Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.872524Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.872533Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-11-05T05:02:40.872545Z DEBUG ramu_rs::controller: issue cmd cmd=PRE clk=51 [INFO] [stdout] 2025-11-05T05:02:40.872554Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.872565Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.872576Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.872587Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2025-11-05T05:02:40.872600Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=REF current=56 future=67 [INFO] [stdout] 2025-11-05T05:02:40.872615Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=SRE current=0 future=67 [INFO] [stdout] 2025-11-05T05:02:40.872629Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=PRE timing.cmd=ACT current=56 future=67 [INFO] [stdout] 2025-11-05T05:02:40.872646Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.872654Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.872664Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.872671Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.872683Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.872691Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.872701Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.872713Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.872723Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.872732Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.872741Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.872750Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.872760Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.872772Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.872782Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.872790Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.872802Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.872811Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.872822Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.872832Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.872842Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.872851Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.872860Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.872869Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.872880Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.872889Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.872899Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.872909Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.872919Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.872928Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.872938Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.872947Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-11-05T05:02:40.872958Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=67 [INFO] [stdout] 2025-11-05T05:02:40.872969Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.872980Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.872995Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.873006Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2025-11-05T05:02:40.873020Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.873031Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=1 future=67 [INFO] [stdout] 2025-11-05T05:02:40.873048Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=51 future=106 [INFO] [stdout] 2025-11-05T05:02:40.873062Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=67 future=122 [INFO] [stdout] 2025-11-05T05:02:40.873078Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=51 future=68 [INFO] [stdout] 2025-11-05T05:02:40.873093Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=1 future=67 [INFO] [stdout] 2025-11-05T05:02:40.873109Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=17 future=83 [INFO] [stdout] 2025-11-05T05:02:40.873122Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=17 future=83 [INFO] [stdout] 2025-11-05T05:02:40.873139Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=17 future=83 [INFO] [stdout] 2025-11-05T05:02:40.873153Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=17 future=83 [INFO] [stdout] 2025-11-05T05:02:40.873167Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=67 future=122 [INFO] [stdout] 2025-11-05T05:02:40.873184Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=51 future=106 [INFO] [stdout] 2025-11-05T05:02:40.873201Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.873215Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.873235Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.873246Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.873256Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.873266Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.873276Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.873288Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.873298Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.873308Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.873318Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.873345Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.873356Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.873367Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.873377Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.873387Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.873397Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.873407Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.873417Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.873429Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.873439Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.873450Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.873460Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.873492Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.873507Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.873515Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.873525Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.873543Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.873561Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.873577Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.873590Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.873604Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.873614Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.873628Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.873637Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.873651Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.873661Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.873674Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.873684Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.873699Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.873709Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.873723Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.873734Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.873747Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.873757Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.873767Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-11-05T05:02:40.873779Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-11-05T05:02:40.873789Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-11-05T05:02:40.873800Z DEBUG ramu_rs::controller: issue cmd cmd=WR clk=83 [INFO] [stdout] 2025-11-05T05:02:40.873813Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.873824Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.873835Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-11-05T05:02:40.873845Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2025-11-05T05:02:40.873858Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WR current=21 future=87 [INFO] [stdout] 2025-11-05T05:02:40.873873Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WRA current=21 future=87 [INFO] [stdout] 2025-11-05T05:02:40.873886Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WR current=21 future=87 [INFO] [stdout] 2025-11-05T05:02:40.873899Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WRA current=21 future=87 [INFO] [stdout] 2025-11-05T05:02:40.873914Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RD current=36 future=102 [INFO] [stdout] 2025-11-05T05:02:40.873928Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RDA current=36 future=102 [INFO] [stdout] 2025-11-05T05:02:40.873941Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PREA current=106 future=117 [INFO] [stdout] 2025-11-05T05:02:40.873953Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PDE current=68 future=117 [INFO] [stdout] 2025-11-05T05:02:40.873968Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WR current=23 future=89 [INFO] [stdout] 2025-11-05T05:02:40.873988Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WRA current=23 future=89 [INFO] [stdout] 2025-11-05T05:02:40.874003Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RD current=42 future=108 [INFO] [stdout] 2025-11-05T05:02:40.874016Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RDA current=42 future=108 [INFO] [stdout] 2025-11-05T05:02:40.874029Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=WR timing.cmd=PRE current=106 future=117 [INFO] [stdout] 2025-11-05T05:02:40.874043Z DEBUG ramu_rs::controller: write request finished req=Request { addr: 8192, addr_vec: [0, 0, 0, 0, 1, 0], done_setup: true, req_type: Write, arrival_time: 0, finish_time: 83 } [INFO] [stdout] 2025-11-05T05:02:40.874058Z 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] Failed to init tracing: a global default trace dispatcher has already been set [INFO] [stdout] [INFO] [stdout] thread 'controller::tests::test_controller_simple_read' (25) panicked at src/controller.rs:300:9: [INFO] [stdout] assertion failed: controller.finished_queue.is_empty() [INFO] [stdout] stack backtrace: [INFO] [stdout] 0: 0x63fd3cfdabe2 - std::backtrace_rs::backtrace::libunwind::trace::h62f3c6bea0fedab3 [INFO] [stdout] at /rustc/f8297e351a40c1439a467bbbb6879088047f50b3/library/std/src/../../backtrace/src/backtrace/libunwind.rs:117:9 [INFO] [stdout] 1: 0x63fd3cfdabe2 - std::backtrace_rs::backtrace::trace_unsynchronized::hc41aaca6c0af0bde [INFO] [stdout] at /rustc/f8297e351a40c1439a467bbbb6879088047f50b3/library/std/src/../../backtrace/src/backtrace/mod.rs:66:14 [INFO] [stdout] 2: 0x63fd3cfdabe2 - std::sys::backtrace::_print_fmt::h33ac2b97007106cc [INFO] [stdout] at /rustc/f8297e351a40c1439a467bbbb6879088047f50b3/library/std/src/sys/backtrace.rs:66:9 [INFO] [stdout] 3: 0x63fd3cfdabe2 - ::fmt::h4e0a3aeea0f9c085 [INFO] [stdout] at /rustc/f8297e351a40c1439a467bbbb6879088047f50b3/library/std/src/sys/backtrace.rs:39:26 [INFO] [stdout] 4: 0x63fd3cfec04f - core::fmt::rt::Argument::fmt::h1edd6a3e00b22f10 [INFO] [stdout] at /rustc/f8297e351a40c1439a467bbbb6879088047f50b3/library/core/src/fmt/rt.rs:173:76 [INFO] [stdout] 5: 0x63fd3cfec04f - core::fmt::write::hecf68a131630c74d [INFO] [stdout] at /rustc/f8297e351a40c1439a467bbbb6879088047f50b3/library/core/src/fmt/mod.rs:1468:25 [INFO] [stdout] 6: 0x63fd3cfa7e81 - std::io::default_write_fmt::ha6b238eff7f0ef8a [INFO] [stdout] at /rustc/f8297e351a40c1439a467bbbb6879088047f50b3/library/std/src/io/mod.rs:639:11 [INFO] [stdout] 7: 0x63fd3cfa7e81 - std::io::Write::write_fmt::h9846fe3d2a36c1ea [INFO] [stdout] at /rustc/f8297e351a40c1439a467bbbb6879088047f50b3/library/std/src/io/mod.rs:1954:13 [INFO] [stdout] 8: 0x63fd3cfb3f52 - std::sys::backtrace::BacktraceLock::print::h75160192768e5621 [INFO] [stdout] at /rustc/f8297e351a40c1439a467bbbb6879088047f50b3/library/std/src/sys/backtrace.rs:42:9 [INFO] [stdout] 9: 0x63fd3cfb8c4f - std::panicking::default_hook::{{closure}}::h14d82797cfb1ddcb [INFO] [stdout] at /rustc/f8297e351a40c1439a467bbbb6879088047f50b3/library/std/src/panicking.rs:301:27 [INFO] [stdout] 10: 0x63fd3cfb8ae1 - std::panicking::default_hook::h63f9bf8161c5d325 [INFO] [stdout] at /rustc/f8297e351a40c1439a467bbbb6879088047f50b3/library/std/src/panicking.rs:325:9 [INFO] [stdout] 11: 0x63fd3cdc935e - as core::ops::function::Fn>::call::hb8126f8384f98101 [INFO] [stdout] at /rustc/f8297e351a40c1439a467bbbb6879088047f50b3/library/alloc/src/boxed.rs:1999:9 [INFO] [stdout] 12: 0x63fd3cdc935e - test::test_main_with_exit_callback::{{closure}}::hae96ae0cd2f2ce70 [INFO] [stdout] at /rustc/f8297e351a40c1439a467bbbb6879088047f50b3/library/test/src/lib.rs:145:21 [INFO] [stdout] 13: 0x63fd3cfb930f - as core::ops::function::Fn>::call::ha703f6686c81d0c6 [INFO] [stdout] at /rustc/f8297e351a40c1439a467bbbb6879088047f50b3/library/alloc/src/boxed.rs:1999:9 [INFO] [stdout] 14: 0x63fd3cfb930f - std::panicking::panic_with_hook::h3173740e06bd0752 [INFO] [stdout] at /rustc/f8297e351a40c1439a467bbbb6879088047f50b3/library/std/src/panicking.rs:842:13 [INFO] [stdout] 15: 0x63fd3cfb9136 - std::panicking::panic_handler::{{closure}}::hbac492c61eb56a87 [INFO] [stdout] at /rustc/f8297e351a40c1439a467bbbb6879088047f50b3/library/std/src/panicking.rs:700:13 [INFO] [stdout] 16: 0x63fd3cfb4099 - std::sys::backtrace::__rust_end_short_backtrace::haa3eac3df9535320 [INFO] [stdout] at /rustc/f8297e351a40c1439a467bbbb6879088047f50b3/library/std/src/sys/backtrace.rs:174:18 [INFO] [stdout] 17: 0x63fd3cf9c4bd - __rustc[de0091b922c53d7e]::rust_begin_unwind [INFO] [stdout] at /rustc/f8297e351a40c1439a467bbbb6879088047f50b3/library/std/src/panicking.rs:698:5 [INFO] [stdout] 18: 0x63fd3cff57d0 - core::panicking::panic_fmt::h5138da2ef87be35b [INFO] [stdout] at /rustc/f8297e351a40c1439a467bbbb6879088047f50b3/library/core/src/panicking.rs:75:14 [INFO] [stdout] 19: 0x63fd3cff57ac - core::panicking::panic::hb515f22c0e98143a [INFO] [stdout] at /rustc/f8297e351a40c1439a467bbbb6879088047f50b3/library/core/src/panicking.rs:145:5 [INFO] [stdout] 20: 0x63fd3cd8b96f - ramu_rs::controller::tests::test_controller_simple_read::h9755a143e2d098fd [INFO] [stdout] at /opt/rustwide/workdir/src/controller.rs:300:9 [INFO] [stdout] 21: 0x63fd3cd8ba77 - ramu_rs::controller::tests::test_controller_simple_read::{{closure}}::h2b697543f4e27bef [INFO] [stdout] at /opt/rustwide/workdir/src/controller.rs:277:37 [INFO] [stdout] 22: 0x63fd3cd9e176 - core::ops::function::FnOnce::call_once::he873ee43b221bf98 [INFO] [stdout] at /rustc/f8297e351a40c1439a467bbbb6879088047f50b3/library/core/src/ops/function.rs:250:5 [INFO] [stdout] 23: 0x63fd3cdc913b - core::ops::function::FnOnce::call_once::h8f50ae93d93b62b4 [INFO] [stdout] at /rustc/f8297e351a40c1439a467bbbb6879088047f50b3/library/core/src/ops/function.rs:250:5 [INFO] [stdout] 24: 0x63fd3cdc913b - test::__rust_begin_short_backtrace::h447963718d05a644 [INFO] [stdout] at /rustc/f8297e351a40c1439a467bbbb6879088047f50b3/library/test/src/lib.rs:663:18 [INFO] [stdout] 25: 0x63fd3cdded75 - test::run_test_in_process::{{closure}}::hf890ba4755ca86c0 [INFO] [stdout] at /rustc/f8297e351a40c1439a467bbbb6879088047f50b3/library/test/src/lib.rs:686:74 [INFO] [stdout] 26: 0x63fd3cdded75 - as core::ops::function::FnOnce<()>>::call_once::h31e4b2860e583faa [INFO] [stdout] at /rustc/f8297e351a40c1439a467bbbb6879088047f50b3/library/core/src/panic/unwind_safe.rs:274:9 [INFO] [stdout] 27: 0x63fd3cdded75 - std::panicking::catch_unwind::do_call::hec7cdbbe797e2cab [INFO] [stdout] at /rustc/f8297e351a40c1439a467bbbb6879088047f50b3/library/std/src/panicking.rs:590:40 [INFO] [stdout] 28: 0x63fd3cdded75 - std::panicking::catch_unwind::h24d3b93458b5ba67 [INFO] [stdout] at /rustc/f8297e351a40c1439a467bbbb6879088047f50b3/library/std/src/panicking.rs:553:19 [INFO] [stdout] 29: 0x63fd3cdded75 - std::panic::catch_unwind::h46eeec7cf9c9336c [INFO] [stdout] at /rustc/f8297e351a40c1439a467bbbb6879088047f50b3/library/std/src/panic.rs:359:14 [INFO] [stdout] 30: 0x63fd3cdded75 - test::run_test_in_process::h290de6e559006104 [INFO] [stdout] at /rustc/f8297e351a40c1439a467bbbb6879088047f50b3/library/test/src/lib.rs:686:27 [INFO] [stdout] 31: 0x63fd3cdded75 - test::run_test::{{closure}}::h26eeb2c5f7e9a995 [INFO] [stdout] at /rustc/f8297e351a40c1439a467bbbb6879088047f50b3/library/test/src/lib.rs:607:43 [INFO] [stdout] 32: 0x63fd3cdb5574 - test::run_test::{{closure}}::h85af00882daabeaa [INFO] [stdout] at /rustc/f8297e351a40c1439a467bbbb6879088047f50b3/library/test/src/lib.rs:637:41 [INFO] [stdout] 33: 0x63fd3cdb5574 - std::sys::backtrace::__rust_begin_short_backtrace::h9d9305dda51fa5f2 [INFO] [stdout] at /rustc/f8297e351a40c1439a467bbbb6879088047f50b3/library/std/src/sys/backtrace.rs:158:18 [INFO] [stdout] 34: 0x63fd3cdb8f1a - std::thread::Builder::spawn_unchecked_::{{closure}}::{{closure}}::hc6aada8b43f0527b [INFO] [stdout] at /rustc/f8297e351a40c1439a467bbbb6879088047f50b3/library/std/src/thread/mod.rs:559:17 [INFO] [stdout] 35: 0x63fd3cdb8f1a - as core::ops::function::FnOnce<()>>::call_once::ha89fe5505c1206f5 [INFO] [stdout] at /rustc/f8297e351a40c1439a467bbbb6879088047f50b3/library/core/src/panic/unwind_safe.rs:274:9 [INFO] [stdout] 36: 0x63fd3cdb8f1a - std::panicking::catch_unwind::do_call::he3e0bef721d99583 [INFO] [stdout] at /rustc/f8297e351a40c1439a467bbbb6879088047f50b3/library/std/src/panicking.rs:590:40 [INFO] [stdout] 37: 0x63fd3cdb8f1a - std::panicking::catch_unwind::ha8241964d3d773cd [INFO] [stdout] at /rustc/f8297e351a40c1439a467bbbb6879088047f50b3/library/std/src/panicking.rs:553:19 [INFO] [stdout] 38: 0x63fd3cdb8f1a - std::panic::catch_unwind::ha8554bc7696cae72 [INFO] [stdout] at /rustc/f8297e351a40c1439a467bbbb6879088047f50b3/library/std/src/panic.rs:359:14 [INFO] [stdout] 39: 0x63fd3cdb8f1a - std::thread::Builder::spawn_unchecked_::{{closure}}::he06f1f62b4c90f8d [INFO] [stdout] at /rustc/f8297e351a40c1439a467bbbb6879088047f50b3/library/std/src/thread/mod.rs:557:30 [INFO] [stdout] 40: 0x63fd3cdb8f1a - core::ops::function::FnOnce::call_once{{vtable.shim}}::ha7fd20ecae19b9b9 [INFO] [stdout] at /rustc/f8297e351a40c1439a467bbbb6879088047f50b3/library/core/src/ops/function.rs:250:5 [INFO] [stdout] 41: 0x63fd3cfaf27f - as core::ops::function::FnOnce>::call_once::h43642ed9c40e0ab2 [INFO] [stdout] at /rustc/f8297e351a40c1439a467bbbb6879088047f50b3/library/alloc/src/boxed.rs:1985:9 [INFO] [stdout] 42: 0x63fd3cfaf27f - std::sys::thread::unix::Thread::new::thread_start::h38da0f633f090ce2 [INFO] [stdout] at /rustc/f8297e351a40c1439a467bbbb6879088047f50b3/library/std/src/sys/thread/unix.rs:126:17 [INFO] [stdout] 43: 0x7cfb2a2d4aa4 - [INFO] [stdout] 44: 0x7cfb2a361a64 - 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.03s [INFO] [stdout] [INFO] [stderr] error: test failed, to rerun pass `--lib` [INFO] running `Command { std: "docker" "inspect" "463ba0564655214363baac75108610b2b16000c1b116f57f459a4609fc87e727", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "463ba0564655214363baac75108610b2b16000c1b116f57f459a4609fc87e727", kill_on_drop: false }` [INFO] [stdout] 463ba0564655214363baac75108610b2b16000c1b116f57f459a4609fc87e727