[INFO] fetching crate ramu_rs 0.1.1...
[INFO] testing ramu_rs-0.1.1 against master#350d0ef0ec0493e6d21cfb265cb8211a0e74d766 for pr-145330-1
[INFO] extracting crate ramu_rs 0.1.1 into /workspace/builds/worker-4-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-4-tc1/source/Cargo.toml
[INFO] validating manifest of crates.io crate ramu_rs 0.1.1 on toolchain 350d0ef0ec0493e6d21cfb265cb8211a0e74d766
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+350d0ef0ec0493e6d21cfb265cb8211a0e74d766" "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" "+350d0ef0ec0493e6d21cfb265cb8211a0e74d766" "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 73 packages to latest compatible versions
[INFO] [stderr]       Adding enum-as-inner v0.5.1 (available: v0.6.1)
[INFO] [stderr]       Adding num_enum v0.5.11 (available: v0.7.4)
[INFO] [stderr]       Adding toml v0.5.11 (available: v0.9.7)
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+350d0ef0ec0493e6d21cfb265cb8211a0e74d766" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] [stderr]     Blocking waiting for file lock on package cache
[INFO] [stderr]     Blocking waiting for file lock on package cache
[INFO] [stderr]  Downloading crates ...
[INFO] [stderr]   Downloaded enum-as-inner v0.5.1
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-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:e90291280db7d1fac5b66fc6dad9f9662629e7365a55743daf9bdf73ebc4ea79" "/opt/rustwide/cargo-home/bin/cargo" "+350d0ef0ec0493e6d21cfb265cb8211a0e74d766" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }`
[INFO] [stdout] f6068846c0d7d303d921d40ccb62e7ab3495ddcf6ab96806ea046f4e337af2a5
[INFO] running `Command { std: "docker" "start" "-a" "f6068846c0d7d303d921d40ccb62e7ab3495ddcf6ab96806ea046f4e337af2a5", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "f6068846c0d7d303d921d40ccb62e7ab3495ddcf6ab96806ea046f4e337af2a5", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "f6068846c0d7d303d921d40ccb62e7ab3495ddcf6ab96806ea046f4e337af2a5", kill_on_drop: false }`
[INFO] [stdout] f6068846c0d7d303d921d40ccb62e7ab3495ddcf6ab96806ea046f4e337af2a5
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc1/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:e90291280db7d1fac5b66fc6dad9f9662629e7365a55743daf9bdf73ebc4ea79" "/opt/rustwide/cargo-home/bin/cargo" "+350d0ef0ec0493e6d21cfb265cb8211a0e74d766" "build" "--frozen" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] 1ef27edf73403b1540ce6debcec58ea17d390e54e2f758bd756edfc12cb7ed41
[INFO] running `Command { std: "docker" "start" "-a" "1ef27edf73403b1540ce6debcec58ea17d390e54e2f758bd756edfc12cb7ed41", 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 winnow v0.5.40
[INFO] [stderr]    Compiling toml_datetime v0.6.11
[INFO] [stderr]    Compiling regex-syntax v0.8.6
[INFO] [stderr]    Compiling cxxbridge-flags v1.0.186
[INFO] [stderr]    Compiling tracing-core v0.1.34
[INFO] [stderr]    Compiling link-cplusplus v1.0.12
[INFO] [stderr]    Compiling sharded-slab v0.1.7
[INFO] [stderr]    Compiling thread_local v1.1.9
[INFO] [stderr]    Compiling nu-ansi-term v0.50.1
[INFO] [stderr]    Compiling foldhash v0.2.0
[INFO] [stderr]    Compiling toml v0.5.11
[INFO] [stderr]    Compiling cxx v1.0.186
[INFO] [stderr]    Compiling indexmap v2.11.4
[INFO] [stderr]    Compiling tracing-log v0.2.0
[INFO] [stderr]    Compiling tracing v0.1.41
[INFO] [stderr]    Compiling enum-as-inner v0.5.1
[INFO] [stderr]    Compiling toml_edit v0.19.15
[INFO] [stderr]    Compiling cxxbridge-macro v1.0.186
[INFO] [stderr]    Compiling regex-automata v0.4.11
[INFO] [stderr]    Compiling proc-macro-crate v1.3.1
[INFO] [stderr]    Compiling num_enum_derive v0.5.11
[INFO] [stderr]    Compiling num_enum v0.5.11
[INFO] [stderr]    Compiling matchers v0.2.0
[INFO] [stderr]    Compiling tracing-subscriber v0.3.20
[INFO] [stderr]    Compiling ramu_rs v0.1.1 (/opt/rustwide/workdir)
[INFO] [stderr]     Finished `dev` profile [unoptimized + debuginfo] target(s) in 19.33s
[INFO] running `Command { std: "docker" "inspect" "1ef27edf73403b1540ce6debcec58ea17d390e54e2f758bd756edfc12cb7ed41", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "1ef27edf73403b1540ce6debcec58ea17d390e54e2f758bd756edfc12cb7ed41", kill_on_drop: false }`
[INFO] [stdout] 1ef27edf73403b1540ce6debcec58ea17d390e54e2f758bd756edfc12cb7ed41
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc1/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:e90291280db7d1fac5b66fc6dad9f9662629e7365a55743daf9bdf73ebc4ea79" "/opt/rustwide/cargo-home/bin/cargo" "+350d0ef0ec0493e6d21cfb265cb8211a0e74d766" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] 22f06e774aa68e936f9074c6c46ef9cb67ca31af1f184073c50c6ace296dc0b9
[INFO] running `Command { std: "docker" "start" "-a" "22f06e774aa68e936f9074c6c46ef9cb67ca31af1f184073c50c6ace296dc0b9", 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.70s
[INFO] running `Command { std: "docker" "inspect" "22f06e774aa68e936f9074c6c46ef9cb67ca31af1f184073c50c6ace296dc0b9", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "22f06e774aa68e936f9074c6c46ef9cb67ca31af1f184073c50c6ace296dc0b9", kill_on_drop: false }`
[INFO] [stdout] 22f06e774aa68e936f9074c6c46ef9cb67ca31af1f184073c50c6ace296dc0b9
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc1/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:e90291280db7d1fac5b66fc6dad9f9662629e7365a55743daf9bdf73ebc4ea79" "/opt/rustwide/cargo-home/bin/cargo" "+350d0ef0ec0493e6d21cfb265cb8211a0e74d766" "test" "--frozen", kill_on_drop: false }`
[INFO] [stdout] 3200e4400acbe294027bc6c1d7f465d19e351e6ce97eb8fe11de0bf8ba5c89c6
[INFO] running `Command { std: "docker" "start" "-a" "3200e4400acbe294027bc6c1d7f465d19e351e6ce97eb8fe11de0bf8ba5c89c6", kill_on_drop: false }`
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 0.08s
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/ramu_rs-68ae99c1bb8f162d)
[INFO] [stdout] 
[INFO] [stdout] running 8 tests
[INFO] [stdout] 2025-10-02T04:48:30.501746Z  INFO ramu_rs::ddr4: building ddr4
[INFO] [stdout] 2025-10-02T04:48:30.501794Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128]
[INFO] [stdout] 2025-10-02T04:48:30.501819Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7]
[INFO] [stdout] 2025-10-02T04:48:30.501831Z  INFO ramu_rs::ddr4: speed_entry speed_entry=SpeedEntry { rate: 2400, freq: 1200.0, tCK: 0.8333333333333334, nBL: 4, nCCDS: 4, nCCDL: 6, nRTRS: 2, nCL: 16, nRCD: 16, nRP: 16, nCWL: 12, nRAS: 39, nRC: 55, nRTP: 9, nWTRS: 3, nWTRL: 9, nWR: 18, nRRDS: 0, nRRDL: 0, nFAW: 0, nRFC: 0, nREFI: 0, nPD: 6, nXP: 8, nXPDLL: 0, nCKESR: 7, nXS: 0, nXSDLL: 0 }
[INFO] [stdout] 2025-10-02T04:48:30.501883Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.501897Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.501907Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.501917Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.501928Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.501939Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.501951Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.501963Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.501974Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.501984Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.501995Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.502005Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.502016Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: ACT, dist: 4, val: 0, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 39, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.502029Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PRE timing_command=[TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.502041Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PREA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.502052Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 9, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.505444Z  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] test config::tests::dum_config ... 2025-10-02T04:48:30.505544Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.504427Z  INFO ramu_rs::ddr4: building ddr4
[INFO] [stdout] 2025-10-02T04:48:30.505613Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 35, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 50, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.505630Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=REF timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.504475Z  INFO ramu_rs::ddr4: building ddr4
[INFO] [stdout] 2025-10-02T04:48:30.503784Z  INFO ramu_rs::ddr4: building ddr4
[INFO] [stdout] 2025-10-02T04:48:30.505656Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128]
[INFO] [stdout] 2025-10-02T04:48:30.505666Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128]
[INFO] [stdout] 2025-10-02T04:48:30.505671Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7]
[INFO] [stdout] ignored
[INFO] [stdout] 2025-10-02T04:48:30.505677Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7]
[INFO] [stdout] 2025-10-02T04:48:30.504047Z  INFO ramu_rs::ddr4: building ddr4
[INFO] [stdout] 2025-10-02T04:48:30.505642Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDE timing_command=[TimeEntry { cmd: PDX, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.505705Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDX timing_command=[TimeEntry { cmd: RD, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 8, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.505625Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128]
[INFO] [stdout] 2025-10-02T04:48:30.505714Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128]
[INFO] [stdout] 2025-10-02T04:48:30.505731Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRE timing_command=[TimeEntry { cmd: SRX, dist: 1, val: 7, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.505735Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7]
[INFO] [stdout] 2025-10-02T04:48:30.505734Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7]
[INFO] [stdout] 2025-10-02T04:48:30.505744Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRX timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 0, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.505746Z  INFO ramu_rs::ddr4: speed_entry speed_entry=SpeedEntry { rate: 2400, freq: 1200.0, tCK: 0.8333333333333334, nBL: 4, nCCDS: 4, nCCDL: 6, nRTRS: 2, nCL: 16, nRCD: 16, nRP: 16, nCWL: 12, nRAS: 39, nRC: 55, nRTP: 9, nWTRS: 3, nWTRL: 9, nWR: 18, nRRDS: 0, nRRDL: 0, nFAW: 0, nRFC: 0, nREFI: 0, nPD: 6, nXP: 8, nXPDLL: 0, nCKESR: 7, nXS: 0, nXSDLL: 0 }
[INFO] [stdout] 2025-10-02T04:48:30.505749Z  INFO ramu_rs::ddr4: speed_entry speed_entry=SpeedEntry { rate: 2400, freq: 1200.0, tCK: 0.8333333333333334, nBL: 4, nCCDS: 4, nCCDL: 6, nRTRS: 2, nCL: 16, nRCD: 16, nRP: 16, nCWL: 12, nRAS: 39, nRC: 55, nRTP: 9, nWTRS: 3, nWTRL: 9, nWR: 18, nRRDS: 0, nRRDL: 0, nFAW: 0, nRFC: 0, nREFI: 0, nPD: 6, nXP: 8, nXPDLL: 0, nCKESR: 7, nXS: 0, nXSDLL: 0 }
[INFO] [stdout] 2025-10-02T04:48:30.505756Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.505767Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.505777Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.505778Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.505788Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.505789Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.505797Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.505799Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.505801Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.505811Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.505814Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.505815Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.505822Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.505825Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.505828Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.505833Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.505836Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.505840Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.505845Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.505849Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.505851Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.505855Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.505859Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.505862Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.505866Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.505870Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.505873Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.505876Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.505881Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.505883Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.505886Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.505891Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.505896Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.505894Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=ACT timing_command=[TimeEntry { cmd: RD, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 39, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.505900Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.505909Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.505906Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: ACT, dist: 4, val: 0, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 39, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.505681Z  INFO ramu_rs::ddr4: speed_entry speed_entry=SpeedEntry { rate: 2400, freq: 1200.0, tCK: 0.8333333333333334, nBL: 4, nCCDS: 4, nCCDL: 6, nRTRS: 2, nCL: 16, nRCD: 16, nRP: 16, nCWL: 12, nRAS: 39, nRC: 55, nRTP: 9, nWTRS: 3, nWTRL: 9, nWR: 18, nRRDS: 0, nRRDL: 0, nFAW: 0, nRFC: 0, nREFI: 0, nPD: 6, nXP: 8, nXPDLL: 0, nCKESR: 7, nXS: 0, nXSDLL: 0 }
[INFO] [stdout] 2025-10-02T04:48:30.505928Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PRE timing_command=[TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.505940Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PREA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.505952Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 9, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.505959Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.505967Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 34, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 34, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.506002Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.506021Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 35, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 50, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.506033Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=REF timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.506044Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDE timing_command=[TimeEntry { cmd: PDX, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.506054Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDX timing_command=[TimeEntry { cmd: RD, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 8, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.506069Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRE timing_command=[TimeEntry { cmd: SRX, dist: 1, val: 7, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.506080Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRX timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 0, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.506092Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.506114Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.506124Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.506134Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.506148Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.506159Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.506169Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.506180Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.506190Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.506200Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.506210Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.506225Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.506235Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=ACT timing_command=[TimeEntry { cmd: RD, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 39, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.506248Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PRE timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.506258Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.506267Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RD timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 9, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.506278Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WR timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 34, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.506289Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RDA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.506299Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WRA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 50, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.506316Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.506327Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.506342Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.506353Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.506364Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.506375Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.506386Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.506397Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.506425Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.506437Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.506448Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.506459Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.506469Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.506479Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.506490Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.506500Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.506509Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.506519Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.506530Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.506540Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.506549Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.506559Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.506573Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.506583Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.506593Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.506603Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.506613Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.506630Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.506641Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.506663Z  INFO ramu_rs::ddr4: read_latency read_latency=20
[INFO] [stdout] 2025-10-02T04:48:30.506773Z DEBUG ramu_rs::test: addr_1=0 addr_2=8192
[INFO] [stdout] 2025-10-02T04:48:30.506804Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.506818Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.506833Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=1
[INFO] [stdout] 2025-10-02T04:48:30.506844Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.506856Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.506867Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.506878Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.506890Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.506900Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=0 future=1
[INFO] [stdout] 2025-10-02T04:48:30.506914Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=0 future=40
[INFO] [stdout] 2025-10-02T04:48:30.506927Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=0 future=56
[INFO] [stdout] 2025-10-02T04:48:30.506940Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=0 future=2
[INFO] [stdout] 2025-10-02T04:48:30.506954Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=0 future=1
[INFO] [stdout] 2025-10-02T04:48:30.506967Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=0 future=17
[INFO] [stdout] 2025-10-02T04:48:30.506980Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=0 future=17
[INFO] [stdout] 2025-10-02T04:48:30.506993Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=0 future=17
[INFO] [stdout] 2025-10-02T04:48:30.507005Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=0 future=17
[INFO] [stdout] 2025-10-02T04:48:30.507018Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=0 future=56
[INFO] [stdout] 2025-10-02T04:48:30.507031Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=0 future=40
[INFO] [stdout] 2025-10-02T04:48:30.507048Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.507063Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.507072Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.507082Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.507091Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.507109Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.507128Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.507137Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.507145Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.507155Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.507163Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.507172Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.507184Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.507192Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.507200Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.507210Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.507219Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.507236Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.507247Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.507255Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.507264Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.507280Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.507289Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.507299Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.507309Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.507316Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.507325Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.507334Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.507343Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.507352Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.507362Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.507371Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.507381Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.507390Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.507399Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.507428Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.507439Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.507447Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.507456Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.507465Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.507473Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.507482Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.507491Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.507499Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.507507Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.507517Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.507524Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.507533Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.507542Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.507552Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.507561Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.507570Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.507583Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.507592Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.507601Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.507608Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.507617Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.507633Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.507641Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.507650Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.507659Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.507667Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.507676Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.507685Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.507692Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.507701Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.507711Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.507718Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.507731Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.507740Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.507755Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.507764Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.507773Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.507781Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.507789Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.507799Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.507807Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.507816Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.507825Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.507833Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.507842Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.507851Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.507859Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.507868Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.507877Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.507885Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.507894Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.507903Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.507910Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.507919Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.507929Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.507936Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.507945Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.507955Z DEBUG ramu_rs::controller: issue cmd cmd=RD clk=17
[INFO] [stdout] 2025-10-02T04:48:30.507964Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.507975Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.507985Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.507997Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.508009Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RD current=0 future=21
[INFO] [stdout] 2025-10-02T04:48:30.508021Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RDA current=0 future=21
[INFO] [stdout] 2025-10-02T04:48:30.508038Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RD current=0 future=21
[INFO] [stdout] 2025-10-02T04:48:30.508051Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RDA current=0 future=21
[INFO] [stdout] 2025-10-02T04:48:30.508066Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WR current=0 future=27
[INFO] [stdout] 2025-10-02T04:48:30.508079Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WRA current=0 future=27
[INFO] [stdout] 2025-10-02T04:48:30.508092Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PREA current=40 future=26
[INFO] [stdout] 2025-10-02T04:48:30.508112Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PDE current=2 future=38
[INFO] [stdout] 2025-10-02T04:48:30.508125Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RD current=0 future=23
[INFO] [stdout] 2025-10-02T04:48:30.508138Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RDA current=0 future=23
[INFO] [stdout] 2025-10-02T04:48:30.508152Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=RD timing.cmd=PRE current=40 future=26
[INFO] [stdout] 2025-10-02T04:48:30.508175Z DEBUG ramu_rs::controller: read request finished req=Request { addr: 0, addr_vec: [0, 0, 0, 0, 0, 0], done_setup: true, req_type: Read, arrival_time: 0, finish_time: 37 } clk=17 req.finish_time=37
[INFO] [stdout] 2025-10-02T04:48:30.508203Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.508212Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.508227Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.508237Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.508245Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.508254Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.508264Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.508271Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.508280Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.508290Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.508297Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.508306Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.508315Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.508323Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.508332Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.508341Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.508349Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.508358Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.508368Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.508376Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.508384Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.508394Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.508401Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.508427Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.508436Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.508443Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.508451Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.508460Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.508467Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.508475Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.508485Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.508492Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.508502Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.508511Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.508524Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.508533Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.508547Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.508554Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.508563Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.508572Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.508579Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.508588Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.508597Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.508604Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.508612Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.508621Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.508628Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.508638Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.508650Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.508657Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.508669Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.508679Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.508687Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.508695Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.508704Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.508711Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.508719Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.508729Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.508736Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.508745Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.508760Z DEBUG ramu_rs::test: recv req=Request { addr: 0, addr_vec: [0, 0, 0, 0, 0, 0], done_setup: true, req_type: Read, arrival_time: 0, finish_time: 37 }
[INFO] [stdout] 2025-10-02T04:48:30.508770Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.508778Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.508786Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.508795Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.508802Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.508811Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.508821Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.508830Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.508840Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.508852Z DEBUG ramu_rs::controller: issue cmd cmd=PRE clk=40
[INFO] [stdout] 2025-10-02T04:48:30.508862Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.508872Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.508883Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.508895Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1
[INFO] [stdout] 2025-10-02T04:48:30.508908Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=REF current=56 future=56
[INFO] [stdout] 2025-10-02T04:48:30.508925Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=SRE current=0 future=56
[INFO] [stdout] 2025-10-02T04:48:30.508939Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=PRE timing.cmd=ACT current=56 future=56
[INFO] [stdout] 2025-10-02T04:48:30.508960Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.508970Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.508981Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.508989Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.508999Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.509008Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.509018Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.509026Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.509039Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.509058Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.509068Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.509077Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.509088Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.509106Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.509118Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.509125Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.509139Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.509147Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.509157Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.509164Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.509175Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.509184Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.509194Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.509203Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.509213Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.509220Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.509230Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.509238Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.509248Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.509256Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.509267Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.509275Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.509292Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=56
[INFO] [stdout] 2025-10-02T04:48:30.509302Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.509313Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.509325Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.509342Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1
[INFO] [stdout] 2025-10-02T04:48:30.509354Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.509364Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=1 future=56
[INFO] [stdout] 2025-10-02T04:48:30.509378Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=40 future=95
[INFO] [stdout] 2025-10-02T04:48:30.509390Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=56 future=111
[INFO] [stdout] test scheduler::tests::test ... ok
[INFO] [stdout] 2025-10-02T04:48:30.505687Z  INFO ramu_rs::ddr4: speed_entry speed_entry=SpeedEntry { rate: 2400, freq: 1200.0, tCK: 0.8333333333333334, nBL: 4, nCCDS: 4, nCCDL: 6, nRTRS: 2, nCL: 16, nRCD: 16, nRP: 16, nCWL: 12, nRAS: 39, nRC: 55, nRTP: 9, nWTRS: 3, nWTRL: 9, nWR: 18, nRRDS: 0, nRRDL: 0, nFAW: 0, nRFC: 0, nREFI: 0, nPD: 6, nXP: 8, nXPDLL: 0, nCKESR: 7, nXS: 0, nXSDLL: 0 }
[INFO] [stdout] test utils::tests::test_addr ... ok
[INFO] [stdout] 2025-10-02T04:48:30.505971Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.509484Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.509490Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.509504Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.509507Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.509516Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.509519Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.509527Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.509531Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.509540Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.509543Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.509552Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.509555Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.509564Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.509566Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.509576Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.509580Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.509587Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.509590Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.509598Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.509601Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.509609Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.509612Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: ACT, dist: 4, val: 0, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 39, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.509620Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.509625Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PRE timing_command=[TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.509631Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: ACT, dist: 4, val: 0, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 39, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.509646Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PRE timing_command=[TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.509645Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PREA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.509657Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PREA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.509659Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 9, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.509669Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 9, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.509677Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 34, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 34, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.509402Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=38 future=57
[INFO] [stdout] 2025-10-02T04:48:30.509749Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.509769Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 35, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 50, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.509771Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=1 future=56
[INFO] [stdout] 2025-10-02T04:48:30.509783Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=REF timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.509792Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=17 future=72
[INFO] [stdout] 2025-10-02T04:48:30.509796Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDE timing_command=[TimeEntry { cmd: PDX, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.509806Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=17 future=72
[INFO] [stdout] 2025-10-02T04:48:30.509807Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDX timing_command=[TimeEntry { cmd: RD, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 8, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.509820Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=17 future=72
[INFO] [stdout] 2025-10-02T04:48:30.509824Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRE timing_command=[TimeEntry { cmd: SRX, dist: 1, val: 7, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.509835Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRX timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 0, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.509834Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=17 future=72
[INFO] [stdout] 2025-10-02T04:48:30.509847Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.509849Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=56 future=111
[INFO] [stdout] 2025-10-02T04:48:30.509858Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.509863Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=40 future=95
[INFO] [stdout] 2025-10-02T04:48:30.509868Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.509881Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.509879Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.509891Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.509891Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.509901Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.509904Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.509915Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.509915Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.509925Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.509927Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.505918Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.509937Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.509948Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.509958Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.509935Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.509969Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.509976Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.509968Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: ACT, dist: 4, val: 0, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 39, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.509979Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=ACT timing_command=[TimeEntry { cmd: RD, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 39, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.509989Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.509992Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PRE timing_command=[TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.509993Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PRE timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.510000Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.510005Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PREA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.510008Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510013Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.510019Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RD timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 9, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.510022Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.510017Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 9, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.510030Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WR timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 34, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.510033Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.510034Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 34, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 34, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.510044Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.510041Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RDA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.510053Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.510049Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.505908Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PRE timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.510054Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WRA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 50, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.510082Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510063Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.510096Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510104Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510111Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RD timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 9, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.510113Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.510116Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510123Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WR timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 34, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.510126Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.510126Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510134Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RDA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.510137Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.510138Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510145Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WRA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 50, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.510149Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.510150Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510156Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510158Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.510161Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510165Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510169Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.510172Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510174Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510180Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.510182Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510184Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510189Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.510192Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510193Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510200Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.510202Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510204Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510212Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.510213Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510214Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510221Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.510223Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510224Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510231Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.510233Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510235Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510242Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.510245Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510246Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510251Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.510254Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510257Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510261Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.510264Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510268Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510272Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.510274Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510278Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510281Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.510285Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510288Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510291Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.510295Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510299Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510302Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.510305Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510310Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510311Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.510315Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510320Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510322Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.510326Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510331Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510334Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.510336Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510342Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510345Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.510346Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510353Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510355Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.510356Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510363Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510366Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.510366Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510373Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510376Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.510377Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510383Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510386Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.510387Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510393Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510398Z  INFO ramu_rs::ddr4: read_latency read_latency=20
[INFO] [stdout] 2025-10-02T04:48:30.510398Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.510419Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510429Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.510431Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510440Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.510441Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510449Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.510452Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510457Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.510462Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.510466Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.510472Z  INFO ramu_rs::ddr4: read_latency read_latency=20
[INFO] [stdout] 2025-10-02T04:48:30.510477Z DEBUG ramu_rs::controller: issue cmd cmd=WR clk=72
[INFO] [stdout] 2025-10-02T04:48:30.510486Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.510497Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.510508Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.510518Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1
[INFO] [stdout] 2025-10-02T04:48:30.510530Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WR current=0 future=76
[INFO] [stdout] 2025-10-02T04:48:30.510531Z DEBUG ramu_rs::test: addr_1=0 addr_2=8192
[INFO] [stdout] 2025-10-02T04:48:30.510543Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WRA current=0 future=76
[INFO] [stdout] 2025-10-02T04:48:30.510551Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.510557Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WR current=27 future=76
[INFO] [stdout] 2025-10-02T04:48:30.510562Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.510569Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WRA current=27 future=76
[INFO] [stdout] 2025-10-02T04:48:30.510573Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=1
[INFO] [stdout] 2025-10-02T04:48:30.510585Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.510583Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RD current=21 future=91
[INFO] [stdout] 2025-10-02T04:48:30.510589Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.510596Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.510597Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RDA current=21 future=91
[INFO] [stdout] 2025-10-02T04:48:30.510602Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.510607Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.510610Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PREA current=95 future=106
[INFO] [stdout] 2025-10-02T04:48:30.510613Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=0
[INFO] [stdout] 2025-10-02T04:48:30.510617Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.510622Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PDE current=57 future=106
[INFO] [stdout] 2025-10-02T04:48:30.510624Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.510628Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.510641Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.510640Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WR current=0 future=78
[INFO] [stdout] 2025-10-02T04:48:30.510645Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=0 future=1
[INFO] [stdout] 2025-10-02T04:48:30.510652Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.510653Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WRA current=0 future=78
[INFO] [stdout] 2025-10-02T04:48:30.510659Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=0 future=40
[INFO] [stdout] 2025-10-02T04:48:30.510662Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.510666Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RD current=23 future=97
[INFO] [stdout] 2025-10-02T04:48:30.510674Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.510674Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=0 future=56
[INFO] [stdout] 2025-10-02T04:48:30.510678Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RDA current=23 future=97
[INFO] [stdout] 2025-10-02T04:48:30.510684Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=0 future=0
[INFO] [stdout] 2025-10-02T04:48:30.510687Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=0 future=2
[INFO] [stdout] 2025-10-02T04:48:30.510691Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=WR timing.cmd=PRE current=95 future=106
[INFO] [stdout] 2025-10-02T04:48:30.510697Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=0 future=39
[INFO] [stdout] 2025-10-02T04:48:30.510700Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=0 future=1
[INFO] [stdout] 2025-10-02T04:48:30.510712Z DEBUG ramu_rs::controller: write request finished req=Request { addr: 8192, addr_vec: [0, 0, 0, 0, 1, 0], done_setup: true, req_type: Write, arrival_time: 0, finish_time: 72 }
[INFO] [stdout] 2025-10-02T04:48:30.510710Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=0 future=55
[INFO] [stdout] 2025-10-02T04:48:30.510715Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=0 future=17
[INFO] [stdout] 2025-10-02T04:48:30.510723Z DEBUG ramu_rs::test: recv req=Request { addr: 8192, addr_vec: [0, 0, 0, 0, 1, 0], done_setup: true, req_type: Write, arrival_time: 0, finish_time: 72 }
[INFO] [stdout] 2025-10-02T04:48:30.510725Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=0 future=1
[INFO] [stdout] 2025-10-02T04:48:30.510727Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=0 future=17
[INFO] [stdout] 2025-10-02T04:48:30.510743Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=0 future=0
[INFO] [stdout] 2025-10-02T04:48:30.510746Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=0 future=17
[INFO] [stdout] 2025-10-02T04:48:30.510758Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=0 future=16
[INFO] [stdout] 2025-10-02T04:48:30.510759Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=0 future=17
[INFO] [stdout] 2025-10-02T04:48:30.510770Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=0 future=16
[INFO] [stdout] 2025-10-02T04:48:30.510772Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=0 future=56
[INFO] [stdout] 2025-10-02T04:48:30.510782Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=0 future=16
[INFO] [stdout] 2025-10-02T04:48:30.510784Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=0 future=40
[INFO] [stdout] 2025-10-02T04:48:30.510796Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=0 future=16
[INFO] [stdout] 2025-10-02T04:48:30.510803Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.510808Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=0 future=55
[INFO] [stdout] 2025-10-02T04:48:30.510811Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.510821Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.510820Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=0 future=39
[INFO] [stdout] 2025-10-02T04:48:30.510831Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.510835Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.510839Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.510843Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.510848Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.510851Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.510858Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.510860Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.510866Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.510869Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.510875Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.510877Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.510885Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.510886Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.510893Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.510894Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.510902Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.510904Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.510912Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.510913Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.510928Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.510930Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] test test::test_memory_read_and_write ... 2025-10-02T04:48:30.510938Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.510954Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 34, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 34, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.510962Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.510971Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.510968Z  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] ok2025-10-02T04:48:30.510980Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 
[INFO] [stdout] 2025-10-02T04:48:30.510991Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.510939Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.511000Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.511002Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.511009Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.511011Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.511020Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.511020Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.511027Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.511029Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.511036Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.511038Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.511047Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.511047Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.511057Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.511055Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.511065Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.511066Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.511073Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.511076Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.511082Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.511084Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.510983Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 35, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 50, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.511118Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.511140Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.511165Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.511177Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.511177Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.511185Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.511187Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.511195Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.511197Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.511205Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.511207Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.511213Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.511214Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.511223Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.511224Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.511232Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.511235Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.511240Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.511243Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.511250Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.511252Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.511260Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.511262Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.511268Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.511272Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.511278Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.511281Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.511288Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.511292Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.511296Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.511301Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.511305Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.511310Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.511316Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.511320Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.511324Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.511328Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.511333Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.511338Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.511343Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.511349Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.511351Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.511357Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.511361Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.511367Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.511371Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.511377Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.511379Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.511386Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.511388Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.511395Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.511519Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.511561Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.511579Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.511592Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.511608Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.511618Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.511636Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.511645Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.511662Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.511673Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.511688Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.511698Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.511715Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.511723Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.511737Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.511747Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.511762Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.511772Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.511790Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.511809Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.511824Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.511841Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.511856Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.511872Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.511890Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.511904Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.511920Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.511937Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.511952Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.511967Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.511984Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.511998Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.512013Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.512029Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.512045Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.512061Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.512078Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.512093Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.512119Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.512139Z DEBUG ramu_rs::controller: issue cmd cmd=WR clk=17
[INFO] [stdout] 2025-10-02T04:48:30.512156Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.512174Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.512191Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.512209Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.512229Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WR current=0 future=21
[INFO] [stdout] 2025-10-02T04:48:30.512252Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WRA current=0 future=21
[INFO] [stdout] 2025-10-02T04:48:30.512273Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WR current=0 future=21
[INFO] [stdout] 2025-10-02T04:48:30.512292Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WRA current=0 future=21
[INFO] [stdout] 2025-10-02T04:48:30.512310Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RD current=0 future=36
[INFO] [stdout] 2025-10-02T04:48:30.512326Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RDA current=0 future=36
[INFO] [stdout] 2025-10-02T04:48:30.512351Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PREA current=40 future=51
[INFO] [stdout] 2025-10-02T04:48:30.512372Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PDE current=2 future=51
[INFO] [stdout] 2025-10-02T04:48:30.512394Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WR current=0 future=23
[INFO] [stdout] 2025-10-02T04:48:30.512435Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WRA current=0 future=23
[INFO] [stdout] 2025-10-02T04:48:30.512454Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RD current=0 future=42
[INFO] [stdout] 2025-10-02T04:48:30.512472Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RDA current=0 future=42
[INFO] [stdout] 2025-10-02T04:48:30.512493Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=WR timing.cmd=PRE current=40 future=51
[INFO] [stdout] 2025-10-02T04:48:30.512513Z DEBUG ramu_rs::controller: write request finished req=Request { addr: 0, addr_vec: [0, 0, 0, 0, 0, 0], done_setup: true, req_type: Write, arrival_time: 0, finish_time: 17 }
[INFO] [stdout] 2025-10-02T04:48:30.512541Z DEBUG ramu_rs::test: recv req=Request { addr: 0, addr_vec: [0, 0, 0, 0, 0, 0], done_setup: true, req_type: Write, arrival_time: 0, finish_time: 17 }
[INFO] [stdout] 2025-10-02T04:48:30.512557Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.512572Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.512587Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.512603Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.512619Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.512634Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.512652Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.512665Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.512681Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.512697Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.512710Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.512725Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.512741Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.512755Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.512771Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.512787Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.512801Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.512816Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.512832Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.512846Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.512861Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.512877Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.512891Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.512906Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.512923Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.512937Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.512953Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.512968Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.512982Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.512998Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.513014Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.513028Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.513043Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.513059Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.513074Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.513089Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.513114Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.513127Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.513142Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.513158Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.513172Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.513188Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.513205Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.513219Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.513234Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.513250Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.513264Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.513279Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.513295Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.513310Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.513326Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.513343Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.513358Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.513373Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.513390Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.511113Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 35, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 50, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.511428Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=REF timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.515657Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=REF timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.515671Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDE timing_command=[TimeEntry { cmd: PDX, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.515684Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDE timing_command=[TimeEntry { cmd: PDX, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.515692Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDX timing_command=[TimeEntry { cmd: RD, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 8, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.515696Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDX timing_command=[TimeEntry { cmd: RD, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 8, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.515706Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRE timing_command=[TimeEntry { cmd: SRX, dist: 1, val: 7, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.515710Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRE timing_command=[TimeEntry { cmd: SRX, dist: 1, val: 7, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.515717Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRX timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 0, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.515721Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRX timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 0, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.515732Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.515733Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.515742Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.515744Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.515752Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.515754Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.515761Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.515764Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.515772Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.515775Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.515783Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.515786Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.515794Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.515797Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.515808Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.515809Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.515818Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.515820Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.515828Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.515830Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.515837Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.515840Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.515847Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.515850Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.515856Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=ACT timing_command=[TimeEntry { cmd: RD, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 39, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.515860Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=ACT timing_command=[TimeEntry { cmd: RD, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 39, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.515868Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PRE timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.515874Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PRE timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.515879Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.515888Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.515889Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RD timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 9, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.515897Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RD timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 9, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.515899Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WR timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 34, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.515908Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WR timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 34, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.515909Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RDA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.515918Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RDA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.515920Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WRA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 50, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.515928Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WRA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 50, sibling: false }]
[INFO] [stdout] 2025-10-02T04:48:30.515930Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.515939Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.515940Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.515955Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.515956Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.515965Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.515966Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.515975Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.515976Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.515985Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.515988Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.515996Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.515999Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.516006Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.516009Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.516016Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.516019Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.516026Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.516028Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.516036Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.516038Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.516047Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.516049Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.516057Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.516059Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.516067Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.516068Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.516077Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.516078Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.516087Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.516095Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.516106Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.516109Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.516117Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.516119Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.516127Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.516130Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.516138Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.516140Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.516148Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.516150Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.516159Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.516161Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.516169Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.516171Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.516180Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.516181Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.516190Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.516191Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.516201Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.516202Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.516212Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.516213Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.516222Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.516225Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.516232Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.516236Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.516243Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-02T04:48:30.516246Z  INFO ramu_rs::ddr4: read_latency read_latency=20
[INFO] [stdout] 2025-10-02T04:48:30.516253Z  INFO ramu_rs::ddr4: read_latency read_latency=20
[INFO] [stdout] 2025-10-02T04:48:30.516356Z DEBUG ramu_rs::test: addr_1=0 addr_2=8192
[INFO] [stdout] 2025-10-02T04:48:30.516375Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.516364Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: addr=1
[INFO] [stdout] 2025-10-02T04:48:30.516387Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.516400Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=1
[INFO] [stdout] 2025-10-02T04:48:30.516400Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: [0, 0, 0, 0, 0, 0]
[INFO] [stdout] 2025-10-02T04:48:30.516431Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.516443Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.516442Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: 0
[INFO] [stdout] 2025-10-02T04:48:30.516454Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.516459Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: addr=65
[INFO] [stdout] 2025-10-02T04:48:30.516465Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.516477Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.516477Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: [0, 0, 0, 0, 0, 1]
[INFO] [stdout] 2025-10-02T04:48:30.516488Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=0 future=1
[INFO] [stdout] 2025-10-02T04:48:30.516494Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: 64
[INFO] [stdout] 2025-10-02T04:48:30.516502Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=0 future=40
[INFO] [stdout] 2025-10-02T04:48:30.516509Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: addr=257
[INFO] [stdout] 2025-10-02T04:48:30.516518Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=0 future=56
[INFO] [stdout] 2025-10-02T04:48:30.516526Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: [0, 0, 0, 0, 0, 4]
[INFO] [stdout] 2025-10-02T04:48:30.516531Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=0 future=2
[INFO] [stdout] 2025-10-02T04:48:30.516541Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: 256
[INFO] [stdout] 2025-10-02T04:48:30.516545Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=0 future=1
[INFO] [stdout] 2025-10-02T04:48:30.516560Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=0 future=17
[INFO] [stdout] 2025-10-02T04:48:30.516573Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=0 future=17
[INFO] [stdout] 2025-10-02T04:48:30.516585Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=0 future=17
[INFO] [stdout] 2025-10-02T04:48:30.516598Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=0 future=17
[INFO] [stdout] 2025-10-02T04:48:30.516612Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=0 future=56
[INFO] [stdout] 2025-10-02T04:48:30.516634Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=0 future=40
[INFO] [stdout] test ddr4::tests::test_address ... ok
[INFO] [stdout] 2025-10-02T04:48:30.516654Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.516664Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.516667Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.516674Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.516685Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.516688Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.516698Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.516701Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.516706Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.516711Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.516719Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.516721Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.516727Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.516731Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.516737Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.516740Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.516747Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.516749Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.516755Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.516759Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.516764Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.516768Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.516773Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.516777Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.516781Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.516787Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.516790Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.516796Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.516799Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.516806Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.516807Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.516816Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.516817Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.516825Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.516826Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.516834Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.516836Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.516844Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.516846Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.516853Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.516856Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.516862Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.516864Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.516872Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.516874Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.516880Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.516884Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.516889Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.516891Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.516898Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.516900Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.516906Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.516910Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.516915Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.516918Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.516925Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.516928Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.516933Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.516938Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.516942Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.516946Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.516952Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.516955Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.516960Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.516964Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.516969Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.516974Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.516979Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.516983Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.516987Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.516993Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.516996Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.517001Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.517006Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.517010Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.517014Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.517020Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.517023Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.517029Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.517033Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.517039Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.517041Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.517049Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.517050Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.517057Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.517061Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.517066Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.517069Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.517076Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.517078Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.517088Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.517084Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.517107Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.517108Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.517118Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.517121Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.517130Z DEBUG ramu_rs::controller: issue cmd cmd=PRE clk=51
[INFO] [stdout] 2025-10-02T04:48:30.517129Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.517140Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.517139Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.517150Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.517151Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.517157Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.517162Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.517167Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.517172Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1
[INFO] [stdout] 2025-10-02T04:48:30.517177Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.517185Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.517186Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=REF current=56 future=67
[INFO] [stdout] 2025-10-02T04:48:30.517194Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.517203Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.517199Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=SRE current=0 future=67
[INFO] [stdout] 2025-10-02T04:48:30.517211Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.517214Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=PRE timing.cmd=ACT current=56 future=67
[INFO] [stdout] 2025-10-02T04:48:30.517220Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.517228Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.517231Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.517236Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.517239Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.517247Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.517248Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.517255Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.517258Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.517264Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.517265Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.517271Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.517275Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.517281Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.517286Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.517290Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.517294Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.517299Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.517304Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.517307Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.517314Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.517317Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.517323Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.517325Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.517333Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.517335Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.517344Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.517344Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.517353Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.517355Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.517362Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.517364Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.517372Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.517375Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.517381Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.517383Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.517390Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.517392Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.517400Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.517430Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.517440Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.517450Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.517459Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.517472Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.517482Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.517490Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.517499Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.517516Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.517525Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.511399Z DEBUG ramu_rs::controller: issue cmd cmd=RD clk=16
[INFO] [stdout] 2025-10-02T04:48:30.517597Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.517612Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.517624Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.517636Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.517650Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RD current=0 future=20
[INFO] [stdout] 2025-10-02T04:48:30.517663Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RDA current=0 future=20
[INFO] [stdout] 2025-10-02T04:48:30.517676Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RD current=0 future=20
[INFO] [stdout] 2025-10-02T04:48:30.517687Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RDA current=0 future=20
[INFO] [stdout] 2025-10-02T04:48:30.517699Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WR current=0 future=26
[INFO] [stdout] 2025-10-02T04:48:30.517710Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WRA current=0 future=26
[INFO] [stdout] 2025-10-02T04:48:30.517723Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PREA current=39 future=25
[INFO] [stdout] 2025-10-02T04:48:30.517736Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PDE current=1 future=37
[INFO] [stdout] 2025-10-02T04:48:30.517749Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RD current=0 future=22
[INFO] [stdout] 2025-10-02T04:48:30.517761Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RDA current=0 future=22
[INFO] [stdout] 2025-10-02T04:48:30.517773Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=RD timing.cmd=PRE current=39 future=25
[INFO] [stdout] 2025-10-02T04:48:30.517788Z DEBUG ramu_rs::controller: read request finished req=Request { addr: 0, addr_vec: [0, 0, 0, 0, 0, 0], done_setup: true, req_type: Read, arrival_time: 0, finish_time: 36 } clk=16 req.finish_time=36
[INFO] [stdout] 2025-10-02T04:48:30.521451Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.521498Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.521511Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-02T04:48:30.521524Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.521538Z DEBUG ramu_rs::controller: issue cmd cmd=RD clk=17
[INFO] [stdout] 2025-10-02T04:48:30.521550Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.521564Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.521575Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.521586Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.521599Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RD current=0 future=21
[INFO] [stdout] 2025-10-02T04:48:30.521613Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RDA current=0 future=21
[INFO] [stdout] 2025-10-02T04:48:30.521627Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RD current=0 future=21
[INFO] [stdout] 2025-10-02T04:48:30.521640Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RDA current=0 future=21
[INFO] [stdout] 2025-10-02T04:48:30.521653Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WR current=0 future=27
[INFO] [stdout] 2025-10-02T04:48:30.521667Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WRA current=0 future=27
[INFO] [stdout] 2025-10-02T04:48:30.521680Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PREA current=40 future=26
[INFO] [stdout] 2025-10-02T04:48:30.521693Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PDE current=2 future=38
[INFO] [stdout] 2025-10-02T04:48:30.521706Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RD current=0 future=23
[INFO] [stdout] 2025-10-02T04:48:30.521720Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RDA current=0 future=23
[INFO] [stdout] 2025-10-02T04:48:30.521734Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=RD timing.cmd=PRE current=40 future=26
[INFO] [stdout] 2025-10-02T04:48:30.521751Z DEBUG ramu_rs::controller: read request finished req=Request { addr: 0, addr_vec: [0, 0, 0, 0, 0, 0], done_setup: true, req_type: Read, arrival_time: 0, finish_time: 37 } clk=17 req.finish_time=37
[INFO] [stdout] 2025-10-02T04:48:30.521767Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.521776Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.521791Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.521801Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.521809Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.521819Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.521829Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.521837Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.521846Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.521857Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.521865Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.521874Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.521884Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.521891Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.521901Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.521911Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.521919Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.521928Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.521938Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.521946Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.521955Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.521965Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.521974Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.521983Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.521993Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.522003Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.522012Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.522022Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.522030Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.522040Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.522050Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.522058Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.522067Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.522077Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.522086Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.522102Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.522112Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.522120Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.522129Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.522139Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.522147Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.522156Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.522166Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.522174Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.522183Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.522193Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.522201Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.522210Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.522221Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.522229Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.522238Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.522247Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.522256Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.522267Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.522277Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.522285Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.522294Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.522304Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.522313Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.522322Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.522353Z DEBUG ramu_rs::test: recv req=Request { addr: 0, addr_vec: [0, 0, 0, 0, 0, 0], done_setup: true, req_type: Read, arrival_time: 0, finish_time: 37 }
[INFO] [stdout] 2025-10-02T04:48:30.522363Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.522371Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.522381Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.522390Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.522399Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.522426Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.522437Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.522444Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.522452Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-02T04:48:30.522461Z DEBUG ramu_rs::controller: issue cmd cmd=PRE clk=40
[INFO] [stdout] 2025-10-02T04:48:30.522469Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.522479Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.522488Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.522497Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1
[INFO] [stdout] 2025-10-02T04:48:30.522508Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=REF current=56 future=56
[INFO] [stdout] 2025-10-02T04:48:30.522519Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=SRE current=0 future=56
[INFO] [stdout] 2025-10-02T04:48:30.522532Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=PRE timing.cmd=ACT current=56 future=56
[INFO] [stdout] 2025-10-02T04:48:30.522545Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.522552Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.522560Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.522567Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.522575Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.522582Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.522591Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.522597Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.522606Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.522613Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.522621Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.522628Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.522636Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.522643Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.522652Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.522659Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.522667Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.522674Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.522682Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.522689Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.522698Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.522705Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.522713Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.522720Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.522729Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.522736Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.522745Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.522752Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.522760Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.522768Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.522776Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.522783Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.522792Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=56
[INFO] [stdout] 2025-10-02T04:48:30.522800Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.522809Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.522819Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.522829Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1
[INFO] [stdout] 2025-10-02T04:48:30.522839Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.522847Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=1 future=56
[INFO] [stdout] 2025-10-02T04:48:30.522858Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=40 future=95
[INFO] [stdout] 2025-10-02T04:48:30.522869Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=56 future=111
[INFO] [stdout] 2025-10-02T04:48:30.522881Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=38 future=57
[INFO] [stdout] 2025-10-02T04:48:30.522893Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=1 future=56
[INFO] [stdout] 2025-10-02T04:48:30.522905Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=17 future=72
[INFO] [stdout] 2025-10-02T04:48:30.522916Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=17 future=72
[INFO] [stdout] 2025-10-02T04:48:30.522927Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=17 future=72
[INFO] [stdout] 2025-10-02T04:48:30.522939Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=17 future=72
[INFO] [stdout] 2025-10-02T04:48:30.522952Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=56 future=111
[INFO] [stdout] 2025-10-02T04:48:30.522963Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=40 future=95
[INFO] [stdout] 2025-10-02T04:48:30.522977Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.522984Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.522993Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.523003Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.523010Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.523019Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.523028Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.523035Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.523043Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.523052Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.523059Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.523068Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.523077Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.523085Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.523103Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.523112Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.523119Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.523128Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.523137Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.523144Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.523152Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.523161Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.523168Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.523177Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.523187Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.523194Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.523203Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.523212Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.523220Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.523228Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.523237Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.523244Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.523253Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.523262Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.523269Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.523278Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.523287Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.523295Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.523303Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.523312Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.523320Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.523328Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.523337Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.523345Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.523353Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.523362Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-02T04:48:30.523369Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.523377Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-02T04:48:30.523387Z DEBUG ramu_rs::controller: issue cmd cmd=RD clk=72
[INFO] [stdout] 2025-10-02T04:48:30.523394Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.527451Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.527486Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.527497Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1
[INFO] [stdout] 2025-10-02T04:48:30.527512Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RD current=21 future=76
[INFO] [stdout] 2025-10-02T04:48:30.527525Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RDA current=21 future=76
[INFO] [stdout] 2025-10-02T04:48:30.527538Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RD current=21 future=76
[INFO] [stdout] 2025-10-02T04:48:30.527550Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RDA current=21 future=76
[INFO] [stdout] 2025-10-02T04:48:30.527562Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WR current=27 future=82
[INFO] [stdout] 2025-10-02T04:48:30.527574Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WRA current=27 future=82
[INFO] [stdout] 2025-10-02T04:48:30.527586Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PREA current=95 future=81
[INFO] [stdout] 2025-10-02T04:48:30.527597Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PDE current=57 future=93
[INFO] [stdout] 2025-10-02T04:48:30.527610Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RD current=23 future=78
[INFO] [stdout] 2025-10-02T04:48:30.527621Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RDA current=23 future=78
[INFO] [stdout] 2025-10-02T04:48:30.527634Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=RD timing.cmd=PRE current=95 future=81
[INFO] [stdout] 2025-10-02T04:48:30.527650Z DEBUG ramu_rs::controller: read request finished req=Request { addr: 8192, addr_vec: [0, 0, 0, 0, 1, 0], done_setup: true, req_type: Read, arrival_time: 0, finish_time: 92 } clk=72 req.finish_time=92
[INFO] [stdout] 2025-10-02T04:48:30.527670Z DEBUG ramu_rs::test: recv req=Request { addr: 8192, addr_vec: [0, 0, 0, 0, 1, 0], done_setup: true, req_type: Read, arrival_time: 0, finish_time: 92 }
[INFO] [stdout] test test::test_memory_diffrent_row ... ok
[INFO] [stdout] 2025-10-02T04:48:30.517400Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.542948Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.542976Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.542989Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.542998Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.543009Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.543017Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.543027Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.543036Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.543046Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.543054Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.543065Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.543072Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-02T04:48:30.543084Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=67
[INFO] [stdout] 2025-10-02T04:48:30.543106Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.543119Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.543130Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.543140Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1
[INFO] [stdout] 2025-10-02T04:48:30.543153Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.543165Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=1 future=67
[INFO] [stdout] 2025-10-02T04:48:30.543178Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=51 future=106
[INFO] [stdout] 2025-10-02T04:48:30.543190Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=67 future=122
[INFO] [stdout] 2025-10-02T04:48:30.543204Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=51 future=68
[INFO] [stdout] 2025-10-02T04:48:30.543217Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=1 future=67
[INFO] [stdout] 2025-10-02T04:48:30.543234Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=17 future=83
[INFO] [stdout] 2025-10-02T04:48:30.543248Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=17 future=83
[INFO] [stdout] 2025-10-02T04:48:30.543261Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=17 future=83
[INFO] [stdout] 2025-10-02T04:48:30.543273Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=17 future=83
[INFO] [stdout] 2025-10-02T04:48:30.543287Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=67 future=122
[INFO] [stdout] 2025-10-02T04:48:30.543299Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=51 future=106
[INFO] [stdout] 2025-10-02T04:48:30.543316Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.543325Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.543335Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.543345Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.543354Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.543363Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.543373Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.543381Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.543390Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.543400Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.543429Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.543438Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.543447Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.543455Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.543463Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.543473Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.543480Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.543490Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.543499Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.543506Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.543515Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.543524Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.543531Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.543539Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.543548Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.543556Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.543564Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.543574Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.543581Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.543590Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.543599Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.543606Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.543615Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.543624Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.543631Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.543639Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.543649Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.543656Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.543665Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.543675Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.543683Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.543691Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.543701Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.543709Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.543717Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.543728Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-02T04:48:30.543736Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-02T04:48:30.543745Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-02T04:48:30.543756Z DEBUG ramu_rs::controller: issue cmd cmd=WR clk=83
[INFO] [stdout] 2025-10-02T04:48:30.543765Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.543775Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.543786Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-10-02T04:48:30.543796Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1
[INFO] [stdout] 2025-10-02T04:48:30.543809Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WR current=21 future=87
[INFO] [stdout] 2025-10-02T04:48:30.543821Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WRA current=21 future=87
[INFO] [stdout] 2025-10-02T04:48:30.543836Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WR current=21 future=87
[INFO] [stdout] 2025-10-02T04:48:30.543848Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WRA current=21 future=87
[INFO] [stdout] 2025-10-02T04:48:30.543860Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RD current=36 future=102
[INFO] [stdout] 2025-10-02T04:48:30.543873Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RDA current=36 future=102
[INFO] [stdout] 2025-10-02T04:48:30.543885Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PREA current=106 future=117
[INFO] [stdout] 2025-10-02T04:48:30.543898Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PDE current=68 future=117
[INFO] [stdout] 2025-10-02T04:48:30.543912Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WR current=23 future=89
[INFO] [stdout] 2025-10-02T04:48:30.543924Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WRA current=23 future=89
[INFO] [stdout] 2025-10-02T04:48:30.543936Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RD current=42 future=108
[INFO] [stdout] 2025-10-02T04:48:30.543951Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RDA current=42 future=108
[INFO] [stdout] 2025-10-02T04:48:30.543964Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=WR timing.cmd=PRE current=106 future=117
[INFO] [stdout] 2025-10-02T04:48:30.543979Z DEBUG ramu_rs::controller: write request finished req=Request { addr: 8192, addr_vec: [0, 0, 0, 0, 1, 0], done_setup: true, req_type: Write, arrival_time: 0, finish_time: 83 }
[INFO] [stdout] 2025-10-02T04:48:30.543994Z DEBUG ramu_rs::test: recv req=Request { addr: 8192, addr_vec: [0, 0, 0, 0, 1, 0], done_setup: true, req_type: Write, arrival_time: 0, finish_time: 83 }
[INFO] [stdout] test test::test_memory_write ... ok
[INFO] [stdout] test controller::tests::test_controller_simple_read ... FAILED
[INFO] [stdout] 
[INFO] [stdout] failures:
[INFO] [stdout] 
[INFO] [stdout] ---- controller::tests::test_controller_simple_read stdout ----
[INFO] [stdout] 
[INFO] [stdout] thread 'controller::tests::test_controller_simple_read' (24) panicked at src/controller.rs:300:9:
[INFO] [stdout] assertion failed: controller.finished_queue.is_empty()
[INFO] [stdout] stack backtrace:
[INFO] [stdout]    0:     0x599c74ad0d82 - std::backtrace_rs::backtrace::libunwind::trace::h0fb8082ca5562a61
[INFO] [stdout]                                at /rustc/350d0ef0ec0493e6d21cfb265cb8211a0e74d766/library/std/src/../../backtrace/src/backtrace/libunwind.rs:117:9
[INFO] [stdout]    1:     0x599c74ad0d82 - std::backtrace_rs::backtrace::trace_unsynchronized::hfaa258994374a3cd
[INFO] [stdout]                                at /rustc/350d0ef0ec0493e6d21cfb265cb8211a0e74d766/library/std/src/../../backtrace/src/backtrace/mod.rs:66:14
[INFO] [stdout]    2:     0x599c74ad0d82 - std::sys::backtrace::_print_fmt::h11496fe34963a885
[INFO] [stdout]                                at /rustc/350d0ef0ec0493e6d21cfb265cb8211a0e74d766/library/std/src/sys/backtrace.rs:66:9
[INFO] [stdout]    3:     0x599c74ad0d82 - <std::sys::backtrace::BacktraceLock::print::DisplayBacktrace as core::fmt::Display>::fmt::hff1a9408d012ee89
[INFO] [stdout]                                at /rustc/350d0ef0ec0493e6d21cfb265cb8211a0e74d766/library/std/src/sys/backtrace.rs:39:26
[INFO] [stdout]    4:     0x599c74af4c9f - core::fmt::rt::Argument::fmt::hf11195b61445f5d1
[INFO] [stdout]                                at /rustc/350d0ef0ec0493e6d21cfb265cb8211a0e74d766/library/core/src/fmt/rt.rs:173:76
[INFO] [stdout]    5:     0x599c74af4c9f - core::fmt::write::h2f1fc679f228cc52
[INFO] [stdout]                                at /rustc/350d0ef0ec0493e6d21cfb265cb8211a0e74d766/library/core/src/fmt/mod.rs:1468:25
[INFO] [stdout]    6:     0x599c74abd8c3 - std::io::default_write_fmt::h12bd533187bc883d
[INFO] [stdout]                                at /rustc/350d0ef0ec0493e6d21cfb265cb8211a0e74d766/library/std/src/io/mod.rs:639:11
[INFO] [stdout]    7:     0x599c74abd8c3 - std::io::Write::write_fmt::h926a1fdfdcb90065
[INFO] [stdout]                                at /rustc/350d0ef0ec0493e6d21cfb265cb8211a0e74d766/library/std/src/io/mod.rs:1954:13
[INFO] [stdout]    8:     0x599c74ad0bd2 - std::sys::backtrace::BacktraceLock::print::h28bfdbcac6d3828b
[INFO] [stdout]                                at /rustc/350d0ef0ec0493e6d21cfb265cb8211a0e74d766/library/std/src/sys/backtrace.rs:42:9
[INFO] [stdout]    9:     0x599c74abc02c - std::panicking::default_hook::{{closure}}::h1f968e3a24b0e3b4
[INFO] [stdout]                                at /rustc/350d0ef0ec0493e6d21cfb265cb8211a0e74d766/library/std/src/panicking.rs:301:27
[INFO] [stdout]   10:     0x599c74abbea9 - std::panicking::default_hook::h43da101644971931
[INFO] [stdout]                                at /rustc/350d0ef0ec0493e6d21cfb265cb8211a0e74d766/library/std/src/panicking.rs:325:9
[INFO] [stdout]   11:     0x599c748b442e - <alloc::boxed::Box<F,A> as core::ops::function::Fn<Args>>::call::h4b2012949041da5d
[INFO] [stdout]                                at /rustc/350d0ef0ec0493e6d21cfb265cb8211a0e74d766/library/alloc/src/boxed.rs:1985:9
[INFO] [stdout]   12:     0x599c748b442e - test::test_main_with_exit_callback::{{closure}}::h53c9154cdc260357
[INFO] [stdout]                                at /rustc/350d0ef0ec0493e6d21cfb265cb8211a0e74d766/library/test/src/lib.rs:145:21
[INFO] [stdout]   13:     0x599c74abc633 - <alloc::boxed::Box<F,A> as core::ops::function::Fn<Args>>::call::h911f2e3e7e84b764
[INFO] [stdout]                                at /rustc/350d0ef0ec0493e6d21cfb265cb8211a0e74d766/library/alloc/src/boxed.rs:1985:9
[INFO] [stdout]   14:     0x599c74abc633 - std::panicking::panic_with_hook::hb4e916c3e65eccec
[INFO] [stdout]                                at /rustc/350d0ef0ec0493e6d21cfb265cb8211a0e74d766/library/std/src/panicking.rs:842:13
[INFO] [stdout]   15:     0x599c74ad0726 - std::panicking::panic_handler::{{closure}}::hbff715d0475cf1bd
[INFO] [stdout]                                at /rustc/350d0ef0ec0493e6d21cfb265cb8211a0e74d766/library/std/src/panicking.rs:700:13
[INFO] [stdout]   16:     0x599c74ad06b9 - std::sys::backtrace::__rust_end_short_backtrace::hd6f43484e45a4955
[INFO] [stdout]                                at /rustc/350d0ef0ec0493e6d21cfb265cb8211a0e74d766/library/std/src/sys/backtrace.rs:174:18
[INFO] [stdout]   17:     0x599c74abcc5d - __rustc[b29d3319de9a3146]::rust_begin_unwind
[INFO] [stdout]                                at /rustc/350d0ef0ec0493e6d21cfb265cb8211a0e74d766/library/std/src/panicking.rs:698:5
[INFO] [stdout]   18:     0x599c74afca30 - core::panicking::panic_fmt::h5f8d281875be5ff1
[INFO] [stdout]                                at /rustc/350d0ef0ec0493e6d21cfb265cb8211a0e74d766/library/core/src/panicking.rs:75:14
[INFO] [stdout]   19:     0x599c74afc6ac - core::panicking::panic::h7985379807a7ee96
[INFO] [stdout]                                at /rustc/350d0ef0ec0493e6d21cfb265cb8211a0e74d766/library/core/src/panicking.rs:145:5
[INFO] [stdout]   20:     0x599c7489543f - ramu_rs::controller::tests::test_controller_simple_read::h58cca10aee033d7a
[INFO] [stdout]                                at /opt/rustwide/workdir/src/controller.rs:300:9
[INFO] [stdout]   21:     0x599c748950a7 - ramu_rs::controller::tests::test_controller_simple_read::{{closure}}::h967744f34d4ef2e0
[INFO] [stdout]                                at /opt/rustwide/workdir/src/controller.rs:277:37
[INFO] [stdout]   22:     0x599c74890bd6 - core::ops::function::FnOnce::call_once::h414ab91b7f8d9116
[INFO] [stdout]                                at /rustc/350d0ef0ec0493e6d21cfb265cb8211a0e74d766/library/core/src/ops/function.rs:253:5
[INFO] [stdout]   23:     0x599c748b996b - core::ops::function::FnOnce::call_once::haf4e03bb51ef1351
[INFO] [stdout]                                at /rustc/350d0ef0ec0493e6d21cfb265cb8211a0e74d766/library/core/src/ops/function.rs:253:5
[INFO] [stdout]   24:     0x599c748b996b - test::__rust_begin_short_backtrace::h50f5566ee84f2f21
[INFO] [stdout]                                at /rustc/350d0ef0ec0493e6d21cfb265cb8211a0e74d766/library/test/src/lib.rs:663:18
[INFO] [stdout]   25:     0x599c748bcb65 - test::run_test_in_process::{{closure}}::heb3733b71d876eca
[INFO] [stdout]                                at /rustc/350d0ef0ec0493e6d21cfb265cb8211a0e74d766/library/test/src/lib.rs:686:74
[INFO] [stdout]   26:     0x599c748bcb65 - <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once::he2fe41e1b161faa9
[INFO] [stdout]                                at /rustc/350d0ef0ec0493e6d21cfb265cb8211a0e74d766/library/core/src/panic/unwind_safe.rs:272:9
[INFO] [stdout]   27:     0x599c748bcb65 - std::panicking::catch_unwind::do_call::h00aa383d8fd97a09
[INFO] [stdout]                                at /rustc/350d0ef0ec0493e6d21cfb265cb8211a0e74d766/library/std/src/panicking.rs:590:40
[INFO] [stdout]   28:     0x599c748bcb65 - std::panicking::catch_unwind::he482e1914bc21641
[INFO] [stdout]                                at /rustc/350d0ef0ec0493e6d21cfb265cb8211a0e74d766/library/std/src/panicking.rs:553:19
[INFO] [stdout]   29:     0x599c748bcb65 - std::panic::catch_unwind::h86ac9705098f4f22
[INFO] [stdout]                                at /rustc/350d0ef0ec0493e6d21cfb265cb8211a0e74d766/library/std/src/panic.rs:359:14
[INFO] [stdout]   30:     0x599c748bcb65 - test::run_test_in_process::h636a992821e3c6aa
[INFO] [stdout]                                at /rustc/350d0ef0ec0493e6d21cfb265cb8211a0e74d766/library/test/src/lib.rs:686:27
[INFO] [stdout]   31:     0x599c748bcb65 - test::run_test::{{closure}}::he454cc9a192df79f
[INFO] [stdout]                                at /rustc/350d0ef0ec0493e6d21cfb265cb8211a0e74d766/library/test/src/lib.rs:607:43
[INFO] [stdout]   32:     0x599c748e2514 - test::run_test::{{closure}}::haec47455908dff86
[INFO] [stdout]                                at /rustc/350d0ef0ec0493e6d21cfb265cb8211a0e74d766/library/test/src/lib.rs:637:41
[INFO] [stdout]   33:     0x599c748e2514 - std::sys::backtrace::__rust_begin_short_backtrace::h230785972524cdc1
[INFO] [stdout]                                at /rustc/350d0ef0ec0493e6d21cfb265cb8211a0e74d766/library/std/src/sys/backtrace.rs:158:18
[INFO] [stdout]   34:     0x599c748c912a - std::thread::Builder::spawn_unchecked_::{{closure}}::{{closure}}::haa5a562db4cde838
[INFO] [stdout]                                at /rustc/350d0ef0ec0493e6d21cfb265cb8211a0e74d766/library/std/src/thread/mod.rs:559:17
[INFO] [stdout]   35:     0x599c748c912a - <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once::h89254f37a55d0a87
[INFO] [stdout]                                at /rustc/350d0ef0ec0493e6d21cfb265cb8211a0e74d766/library/core/src/panic/unwind_safe.rs:272:9
[INFO] [stdout]   36:     0x599c748c912a - std::panicking::catch_unwind::do_call::h499f5a462f019d9d
[INFO] [stdout]                                at /rustc/350d0ef0ec0493e6d21cfb265cb8211a0e74d766/library/std/src/panicking.rs:590:40
[INFO] [stdout]   37:     0x599c748c912a - std::panicking::catch_unwind::h6736fbbb1a264383
[INFO] [stdout]                                at /rustc/350d0ef0ec0493e6d21cfb265cb8211a0e74d766/library/std/src/panicking.rs:553:19
[INFO] [stdout]   38:     0x599c748c912a - std::panic::catch_unwind::h49ea7bdd1cbee572
[INFO] [stdout]                                at /rustc/350d0ef0ec0493e6d21cfb265cb8211a0e74d766/library/std/src/panic.rs:359:14
[INFO] [stdout]   39:     0x599c748c912a - std::thread::Builder::spawn_unchecked_::{{closure}}::h653dfa62acf32f5a
[INFO] [stdout]                                at /rustc/350d0ef0ec0493e6d21cfb265cb8211a0e74d766/library/std/src/thread/mod.rs:557:30
[INFO] [stdout]   40:     0x599c748c912a - core::ops::function::FnOnce::call_once{{vtable.shim}}::h82582a626a045a45
[INFO] [stdout]                                at /rustc/350d0ef0ec0493e6d21cfb265cb8211a0e74d766/library/core/src/ops/function.rs:253:5
[INFO] [stdout]   41:     0x599c74aa724f - <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once::h4ab26c07513156cc
[INFO] [stdout]                                at /rustc/350d0ef0ec0493e6d21cfb265cb8211a0e74d766/library/alloc/src/boxed.rs:1971:9
[INFO] [stdout]   42:     0x599c74aa724f - std::sys::pal::unix::thread::Thread::new::thread_start::h66ff1bba185a50cf
[INFO] [stdout]                                at /rustc/350d0ef0ec0493e6d21cfb265cb8211a0e74d766/library/std/src/sys/pal/unix/thread.rs:107:17
[INFO] [stdout]   43:     0x759816999aa4 - <unknown>
[INFO] [stdout]   44:     0x759816a26a34 - clone
[INFO] [stdout]   45:                0x0 - <unknown>
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] failures:
[INFO] [stdout]     controller::tests::test_controller_simple_read
[INFO] [stdout] 
[INFO] [stdout] test result: FAILED. 6 passed; 1 failed; 1 ignored; 0 measured; 0 filtered out; finished in 0.05s
[INFO] [stdout] 
[INFO] [stderr] error: test failed, to rerun pass `--lib`
[INFO] running `Command { std: "docker" "inspect" "3200e4400acbe294027bc6c1d7f465d19e351e6ce97eb8fe11de0bf8ba5c89c6", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "3200e4400acbe294027bc6c1d7f465d19e351e6ce97eb8fe11de0bf8ba5c89c6", kill_on_drop: false }`
[INFO] [stdout] 3200e4400acbe294027bc6c1d7f465d19e351e6ce97eb8fe11de0bf8ba5c89c6