[INFO] fetching crate ramu_rs 0.1.1... [INFO] testing ramu_rs-0.1.1 against try#b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b for pr-145330-1 [INFO] extracting crate ramu_rs 0.1.1 into /workspace/builds/worker-4-tc2/source [INFO] started tweaking crates.io crate ramu_rs 0.1.1 [INFO] finished tweaking crates.io crate ramu_rs 0.1.1 [INFO] tweaked toml for crates.io crate ramu_rs 0.1.1 written to /workspace/builds/worker-4-tc2/source/Cargo.toml [INFO] validating manifest of crates.io crate ramu_rs 0.1.1 on toolchain b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b [INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b" "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" "+b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b" "generate-lockfile" "--manifest-path" "Cargo.toml", kill_on_drop: false }` [INFO] [stderr] Updating crates.io index [INFO] [stderr] Locking 73 packages to latest compatible versions [INFO] [stderr] Adding enum-as-inner v0.5.1 (available: v0.6.1) [INFO] [stderr] Adding num_enum v0.5.11 (available: v0.7.4) [INFO] [stderr] Adding toml v0.5.11 (available: v0.9.7) [INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }` [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:e90291280db7d1fac5b66fc6dad9f9662629e7365a55743daf9bdf73ebc4ea79" "/opt/rustwide/cargo-home/bin/cargo" "+b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }` [INFO] [stdout] a0ca3da5bd5b986f9d3914150955cb8802c7a8ff39c5e421ea76b545f687fbde [INFO] running `Command { std: "docker" "start" "-a" "a0ca3da5bd5b986f9d3914150955cb8802c7a8ff39c5e421ea76b545f687fbde", kill_on_drop: false }` [INFO] running `Command { std: "docker" "inspect" "a0ca3da5bd5b986f9d3914150955cb8802c7a8ff39c5e421ea76b545f687fbde", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "a0ca3da5bd5b986f9d3914150955cb8802c7a8ff39c5e421ea76b545f687fbde", kill_on_drop: false }` [INFO] [stdout] a0ca3da5bd5b986f9d3914150955cb8802c7a8ff39c5e421ea76b545f687fbde [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:e90291280db7d1fac5b66fc6dad9f9662629e7365a55743daf9bdf73ebc4ea79" "/opt/rustwide/cargo-home/bin/cargo" "+b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b" "build" "--frozen" "--message-format=json", kill_on_drop: false }` [INFO] [stdout] f085c3bacf4e1473199af681a9ae367adb2fd39885c93502d79ac02705fc21ee [INFO] running `Command { std: "docker" "start" "-a" "f085c3bacf4e1473199af681a9ae367adb2fd39885c93502d79ac02705fc21ee", kill_on_drop: false }` [INFO] [stderr] Compiling hashbrown v0.16.0 [INFO] [stderr] Compiling equivalent v1.0.2 [INFO] [stderr] Compiling syn v1.0.109 [INFO] [stderr] Compiling toml_datetime v0.6.11 [INFO] [stderr] Compiling winnow v0.5.40 [INFO] [stderr] Compiling 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 thread_local v1.1.9 [INFO] [stderr] Compiling sharded-slab v0.1.7 [INFO] [stderr] Compiling foldhash v0.2.0 [INFO] [stderr] Compiling nu-ansi-term v0.50.1 [INFO] [stderr] Compiling toml v0.5.11 [INFO] [stderr] Compiling cxx v1.0.186 [INFO] [stderr] Compiling tracing v0.1.41 [INFO] [stderr] Compiling tracing-log v0.2.0 [INFO] [stderr] Compiling indexmap v2.11.4 [INFO] [stderr] Compiling regex-automata v0.4.11 [INFO] [stderr] Compiling toml_edit v0.19.15 [INFO] [stderr] Compiling cxxbridge-macro v1.0.186 [INFO] [stderr] Compiling enum-as-inner v0.5.1 [INFO] [stderr] Compiling matchers v0.2.0 [INFO] [stderr] Compiling tracing-subscriber v0.3.20 [INFO] [stderr] Compiling proc-macro-crate v1.3.1 [INFO] [stderr] Compiling num_enum_derive v0.5.11 [INFO] [stderr] Compiling num_enum v0.5.11 [INFO] [stderr] Compiling ramu_rs v0.1.1 (/opt/rustwide/workdir) [INFO] [stderr] Finished `dev` profile [unoptimized + debuginfo] target(s) in 17.23s [INFO] running `Command { std: "docker" "inspect" "f085c3bacf4e1473199af681a9ae367adb2fd39885c93502d79ac02705fc21ee", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "f085c3bacf4e1473199af681a9ae367adb2fd39885c93502d79ac02705fc21ee", kill_on_drop: false }` [INFO] [stdout] f085c3bacf4e1473199af681a9ae367adb2fd39885c93502d79ac02705fc21ee [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:e90291280db7d1fac5b66fc6dad9f9662629e7365a55743daf9bdf73ebc4ea79" "/opt/rustwide/cargo-home/bin/cargo" "+b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }` [INFO] [stdout] 0d203c7f78409f4693dbffe692fb843e7e248329a757af63ad76a880c168e285 [INFO] running `Command { std: "docker" "start" "-a" "0d203c7f78409f4693dbffe692fb843e7e248329a757af63ad76a880c168e285", 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.88s [INFO] running `Command { std: "docker" "inspect" "0d203c7f78409f4693dbffe692fb843e7e248329a757af63ad76a880c168e285", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "0d203c7f78409f4693dbffe692fb843e7e248329a757af63ad76a880c168e285", kill_on_drop: false }` [INFO] [stdout] 0d203c7f78409f4693dbffe692fb843e7e248329a757af63ad76a880c168e285 [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-4-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:e90291280db7d1fac5b66fc6dad9f9662629e7365a55743daf9bdf73ebc4ea79" "/opt/rustwide/cargo-home/bin/cargo" "+b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b" "test" "--frozen", kill_on_drop: false }` [INFO] [stdout] ffec98defbf27d28e40b9500f548b9ecf00e9e51cdefb547a17dbfadddc7912c [INFO] running `Command { std: "docker" "start" "-a" "ffec98defbf27d28e40b9500f548b9ecf00e9e51cdefb547a17dbfadddc7912c", kill_on_drop: false }` [INFO] [stderr] Finished `test` profile [unoptimized + debuginfo] target(s) in 0.09s [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:54.198073Z  INFO ramu_rs::ddr4: building ddr4 [INFO] [stdout] 2025-10-02T04:48:54.198108Z  INFO ramu_rs::ddr4: building ddr4 [INFO] [stdout] 2025-10-02T04:48:54.198121Z  INFO ramu_rs::ddr4: building ddr4 [INFO] [stdout] 2025-10-02T04:48:54.198130Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128] [INFO] [stdout] 2025-10-02T04:48:54.198130Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128] [INFO] [stdout] 2025-10-02T04:48:54.198140Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128] [INFO] [stdout] 2025-10-02T04:48:54.198148Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7] [INFO] [stdout] 2025-10-02T04:48:54.198148Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7] [INFO] [stdout] 2025-10-02T04:48:54.198153Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7] [INFO] [stdout] 2025-10-02T04:48:54.198159Z  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:54.198159Z  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:54.198163Z  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:54.198195Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198195Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198202Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198207Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198208Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198217Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198217Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198219Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198228Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198229Z  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:54.198230Z  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:54.198239Z  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:54.198243Z  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:54.198244Z  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:54.198252Z  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:54.198254Z  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:54.198256Z  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:54.198265Z  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:54.198266Z  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:54.198267Z  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:54.198277Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198276Z  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:54.198279Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198288Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198290Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198290Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198299Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198301Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198303Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198309Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198312Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198313Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198320Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198322Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198324Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198330Z  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:54.198334Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198333Z  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:54.198343Z  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:54.198345Z  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:54.198352Z  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:54.198355Z  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:54.198360Z  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:54.198364Z  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:54.198367Z  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:54.198373Z  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:54.198377Z  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:54.198384Z  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:54.198386Z  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:54.198398Z  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:54.198400Z  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:54.198428Z  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:54.198431Z  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:54.198445Z  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:54.198459Z  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:54.198459Z  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:54.198429Z  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:54.198470Z  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:54.198472Z  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:54.198477Z  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:54.198481Z  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:54.198482Z  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:54.198495Z  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:54.198499Z  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:54.198500Z  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:54.198510Z  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:54.198511Z  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:54.198512Z  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:54.198522Z  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:54.198523Z  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:54.198525Z  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:54.198536Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198533Z  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:54.198547Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198558Z  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:54.198560Z  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:54.198569Z  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:54.198571Z  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:54.198581Z  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:54.198584Z  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:54.198592Z  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:54.198596Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198605Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198609Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198616Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198619Z  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:54.198626Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198631Z  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:54.198636Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198644Z  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:54.198647Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198655Z  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:54.198658Z  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:54.198668Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198671Z  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:54.198678Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198682Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198688Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198692Z  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:54.198700Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198704Z  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:54.198712Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198715Z  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:54.198723Z  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:54.198726Z  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:54.198736Z  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:54.198738Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198747Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198749Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198758Z  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:54.198759Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198768Z  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:54.198770Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198780Z  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:54.198781Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198791Z  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:54.198792Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198803Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198805Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198814Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198816Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198824Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198826Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198835Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198836Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198845Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198847Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198855Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198858Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198865Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198868Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198875Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198878Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198886Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198888Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198896Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198899Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198905Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198909Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198917Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198920Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198927Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198931Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198938Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198941Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198948Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198952Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198958Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198962Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198969Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198973Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198979Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198983Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198990Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.198994Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.199000Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.199004Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.199011Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.199015Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.199021Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.199025Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.199033Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.199036Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.199043Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.199051Z  INFO ramu_rs::ddr4: read_latency read_latency=20 [INFO] [stdout] 2025-10-02T04:48:54.199054Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.199066Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.199077Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.199088Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.199108Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.199120Z  INFO ramu_rs::ddr4: read_latency read_latency=20 [INFO] [stdout] 2025-10-02T04:48:54.199126Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: addr=1 [INFO] [stdout] 2025-10-02T04:48:54.199152Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: [0, 0, 0, 0, 0, 0] [INFO] [stdout] 2025-10-02T04:48:54.199169Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: 0 [INFO] [stdout] 2025-10-02T04:48:54.199182Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: addr=65 [INFO] [stdout] 2025-10-02T04:48:54.199196Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: [0, 0, 0, 0, 0, 1] [INFO] [stdout] 2025-10-02T04:48:54.199211Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: 64 [INFO] [stdout] 2025-10-02T04:48:54.199223Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: addr=257 [INFO] [stdout] 2025-10-02T04:48:54.199236Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: [0, 0, 0, 0, 0, 4] [INFO] [stdout] 2025-10-02T04:48:54.199249Z DEBUG ramu_rs::test: addr_1=0 addr_2=8192 [INFO] [stdout] 2025-10-02T04:48:54.199251Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: 256 [INFO] [stdout] 2025-10-02T04:48:54.199270Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.199283Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.199298Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=1 [INFO] [stdout] 2025-10-02T04:48:54.199309Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.199324Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.199335Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.199346Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.199361Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.199373Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=0 future=1 [INFO] [stdout] 2025-10-02T04:48:54.199388Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=0 future=40 [INFO] [stdout] test config::tests::dum_config ... ignored [INFO] [stdout] 2025-10-02T04:48:54.199402Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=0 future=56 [INFO] [stdout] test scheduler::tests::test ... ok [INFO] [stdout] 2025-10-02T04:48:54.199433Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=0 future=2 [INFO] [stdout] 2025-10-02T04:48:54.199447Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=0 future=1 [INFO] [stdout] 2025-10-02T04:48:54.199461Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=0 future=17 [INFO] [stdout] 2025-10-02T04:48:54.199480Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=0 future=17 [INFO] [stdout] test ddr4::tests::test_address ... ok [INFO] [stdout] 2025-10-02T04:48:54.199493Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=0 future=17 [INFO] [stdout] 2025-10-02T04:48:54.199506Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=0 future=17 [INFO] [stdout] 2025-10-02T04:48:54.199519Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=0 future=56 [INFO] [stdout] 2025-10-02T04:48:54.199533Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=0 future=40 [INFO] [stdout] 2025-10-02T04:48:54.199552Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.199567Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] test utils::tests::test_addr ... ok [INFO] [stdout] 2025-10-02T04:48:54.199577Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.199588Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.199599Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.199607Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.199625Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.199633Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.199642Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.199653Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.199661Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.199675Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.199686Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.199704Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.199715Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.199731Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.199739Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.199757Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.199767Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.199776Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.199786Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.199795Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.199803Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.199819Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.199830Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.199845Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.199855Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.199870Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.199878Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.199887Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.199897Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.199909Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.199919Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.199935Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.199944Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.199959Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.199969Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.199984Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.199993Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.200003Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.200013Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.200022Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.200039Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.200048Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.200062Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.200072Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.200086Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.200102Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.200116Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.200124Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.200133Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.200143Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.200161Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.200171Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.200187Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.200196Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.200210Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.200221Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.200234Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.200243Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.200254Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.200263Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.200280Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.200291Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.200307Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.200318Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.200337Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.200347Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.200358Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.200370Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.200378Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.200387Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.198537Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.200457Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.200487Z  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:54.200506Z  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:54.200526Z  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:54.200538Z  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:54.200550Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.200560Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.200575Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.200585Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.200600Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.200610Z  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:54.200629Z  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:54.200641Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.200661Z  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:54.200673Z  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:54.200684Z  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:54.200694Z  INFO ramu_rs::ddr4: building ddr4 [INFO] [stdout] 2025-10-02T04:48:54.200706Z  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:54.200709Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128] [INFO] [stdout] 2025-10-02T04:48:54.200719Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.200742Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.200759Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.200770Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.200782Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.200793Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.200803Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.200813Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.200829Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.200839Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.200853Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.200864Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.200879Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.200913Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.200932Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.200942Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.200952Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.200962Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.200979Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.200990Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.201004Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.201015Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.201030Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.201040Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.201053Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.201063Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.201073Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.201083Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.201105Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.201115Z  INFO ramu_rs::ddr4: read_latency read_latency=20 [INFO] [stdout] 2025-10-02T04:48:54.201236Z DEBUG ramu_rs::test: addr_1=0 addr_2=8192 [INFO] [stdout] 2025-10-02T04:48:54.201255Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.201264Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.201277Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=1 [INFO] [stdout] 2025-10-02T04:48:54.201294Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.201305Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.201321Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.201331Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.201342Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.201352Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=0 future=1 [INFO] [stdout] 2025-10-02T04:48:54.201365Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=0 future=40 [INFO] [stdout] 2025-10-02T04:48:54.201382Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=0 future=56 [INFO] [stdout] 2025-10-02T04:48:54.201402Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=0 future=2 [INFO] [stdout] 2025-10-02T04:48:54.201432Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=0 future=1 [INFO] [stdout] 2025-10-02T04:48:54.201445Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=0 future=17 [INFO] [stdout] 2025-10-02T04:48:54.201458Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=0 future=17 [INFO] [stdout] 2025-10-02T04:48:54.201478Z  INFO ramu_rs::ddr4: building ddr4 [INFO] [stdout] 2025-10-02T04:48:54.201481Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=0 future=17 [INFO] [stdout] 2025-10-02T04:48:54.201497Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128] [INFO] [stdout] 2025-10-02T04:48:54.201497Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=0 future=17 [INFO] [stdout] 2025-10-02T04:48:54.201509Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7] [INFO] [stdout] 2025-10-02T04:48:54.201510Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=0 future=56 [INFO] [stdout] 2025-10-02T04:48:54.201519Z  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:54.201523Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=0 future=40 [INFO] [stdout] 2025-10-02T04:48:54.201567Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.201567Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.201594Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.201603Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.201603Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.201615Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.201616Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.201623Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.201627Z  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:54.201632Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.201642Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.201639Z  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:54.201649Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.201651Z  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:54.201673Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.201683Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.201682Z  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:54.201696Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.201698Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.201705Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.201709Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.201715Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.201720Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.201722Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.201743Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.201751Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.201754Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.201761Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.201765Z  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:54.201769Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.201792Z  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:54.201800Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.201805Z  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:54.201810Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.201819Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.201818Z  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:54.201843Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.201852Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.201852Z  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:54.201863Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.201872Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.201868Z  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:54.201881Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.201882Z  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:54.201889Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.201899Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.201897Z  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:54.201920Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.201929Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.201929Z  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:54.201951Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.201973Z  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:54.201982Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.202000Z  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:54.202007Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.202012Z  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:54.202017Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.202026Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.202025Z  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:54.202049Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.202059Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.202059Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.202080Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.202105Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.202118Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.202120Z  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:54.202128Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.202132Z  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:54.202138Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.202145Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.202144Z  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:54.202154Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.202156Z  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:54.202178Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.202198Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.202219Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.202229Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.202228Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.202240Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.202242Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.202248Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.202252Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.202257Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.202263Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.202267Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.202274Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.202274Z  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:54.202297Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.202317Z  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:54.202338Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.202350Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.202350Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.202359Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.202363Z  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:54.202370Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.202374Z  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:54.202378Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.202385Z  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:54.202387Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.202398Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.202396Z  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:54.202419Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.202421Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.202429Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.202454Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.202469Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.202478Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.202488Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.202495Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.202506Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.202516Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.202529Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.202538Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.202553Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.202561Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.202575Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.202585Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.202593Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.202602Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.202613Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.202621Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.202636Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.202646Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.202658Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.202667Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.202681Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.202689Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.202698Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.202707Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.202715Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.202726Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.202735Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.202750Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.202759Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.202773Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.202780Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.202794Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.202804Z DEBUG ramu_rs::controller: issue cmd cmd=RD clk=17 [INFO] [stdout] 2025-10-02T04:48:54.202813Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.202826Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.202837Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.202853Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.202864Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RD current=0 future=21 [INFO] [stdout] 2025-10-02T04:48:54.202882Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RDA current=0 future=21 [INFO] [stdout] 2025-10-02T04:48:54.202902Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RD current=0 future=21 [INFO] [stdout] 2025-10-02T04:48:54.202914Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RDA current=0 future=21 [INFO] [stdout] 2025-10-02T04:48:54.202932Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WR current=0 future=27 [INFO] [stdout] 2025-10-02T04:48:54.202945Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WRA current=0 future=27 [INFO] [stdout] 2025-10-02T04:48:54.202957Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PREA current=40 future=26 [INFO] [stdout] 2025-10-02T04:48:54.202977Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PDE current=2 future=38 [INFO] [stdout] 2025-10-02T04:48:54.202998Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RD current=0 future=23 [INFO] [stdout] 2025-10-02T04:48:54.203015Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RDA current=0 future=23 [INFO] [stdout] 2025-10-02T04:48:54.203029Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=RD timing.cmd=PRE current=40 future=26 [INFO] [stdout] 2025-10-02T04:48:54.203050Z 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:54.203066Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.203074Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.203088Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.203109Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.203117Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.203131Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.203141Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.203149Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.203159Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.203169Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.203177Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.203187Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.203197Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.203209Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.203218Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.203233Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.203241Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.203254Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.203264Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.203271Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.203280Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.203292Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.203300Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.203313Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.203323Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.203336Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.203345Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.203359Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.203367Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.203376Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.203386Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.203394Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.203418Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.203429Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.203444Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.203453Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.203467Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.203475Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.203488Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.203498Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.203506Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.203517Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.203526Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.203534Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.203543Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.203560Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.203568Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.203582Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.203592Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.203604Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.203613Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.203623Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.203632Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.203641Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.203651Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.203658Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.203675Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.203685Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.203698Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.203706Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.203724Z 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:54.203734Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.203745Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.203754Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.203764Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.203773Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.203782Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.203797Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.203805Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.203821Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.203831Z DEBUG ramu_rs::controller: issue cmd cmd=PRE clk=40 [INFO] [stdout] 2025-10-02T04:48:54.203845Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.203856Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.203866Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.203877Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2025-10-02T04:48:54.203890Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=REF current=56 future=56 [INFO] [stdout] 2025-10-02T04:48:54.203908Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=SRE current=0 future=56 [INFO] [stdout] 2025-10-02T04:48:54.203928Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=PRE timing.cmd=ACT current=56 future=56 [INFO] [stdout] 2025-10-02T04:48:54.203948Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.203956Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.203965Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.203973Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.203990Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.203997Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.204012Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.204020Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.204034Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.204042Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.204051Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.204062Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.204071Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.204079Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.204088Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.204106Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.204116Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.204129Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.204139Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.204151Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.204161Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.204168Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.204179Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.204187Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.204196Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.204204Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.204220Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.204228Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.204242Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.204250Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.204264Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.204272Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.204281Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=56 [INFO] [stdout] 2025-10-02T04:48:54.204292Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.204303Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.204314Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.204332Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2025-10-02T04:48:54.204343Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.204359Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=1 future=56 [INFO] [stdout] 2025-10-02T04:48:54.204377Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=40 future=95 [INFO] [stdout] 2025-10-02T04:48:54.204393Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=56 future=111 [INFO] [stdout] 2025-10-02T04:48:54.200398Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.204434Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=38 future=57 [INFO] [stdout] 2025-10-02T04:48:54.204450Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=1 future=56 [INFO] [stdout] 2025-10-02T04:48:54.204445Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.202432Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.204500Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.204502Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.204527Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.204539Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.204541Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.204554Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.204556Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.204479Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=17 future=72 [INFO] [stdout] 2025-10-02T04:48:54.204578Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.204603Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.204625Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.204639Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.204643Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.204650Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.204655Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.204661Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.204666Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.204671Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.204693Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.204719Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.204731Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.204733Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.204742Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.204745Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.204755Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.204757Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.204765Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.204767Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.204777Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.204775Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.204786Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.204787Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.204810Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.204598Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=17 future=72 [INFO] [stdout] 2025-10-02T04:48:54.204831Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.204852Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.204875Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.204898Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.204917Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.204937Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.204957Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.204967Z DEBUG ramu_rs::controller: issue cmd cmd=RD clk=17 [INFO] [stdout] 2025-10-02T04:48:54.204969Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.204977Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.204980Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.204991Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.204992Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.205002Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.205004Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.205025Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.204890Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=17 future=72 [INFO] [stdout] 2025-10-02T04:48:54.205045Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.205068Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RD current=0 future=21 [INFO] [stdout] 2025-10-02T04:48:54.205072Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.205083Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.205103Z  INFO ramu_rs::ddr4: read_latency read_latency=20 [INFO] [stdout] 2025-10-02T04:48:54.205204Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.205223Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.205235Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=0 [INFO] [stdout] 2025-10-02T04:48:54.205248Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.205266Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.205278Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.205294Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.205304Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.205321Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=0 future=0 [INFO] [stdout] 2025-10-02T04:48:54.205336Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=0 future=39 [INFO] [stdout] 2025-10-02T04:48:54.205349Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=0 future=55 [INFO] [stdout] 2025-10-02T04:48:54.205369Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=0 future=1 [INFO] [stdout] 2025-10-02T04:48:54.205391Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=0 future=0 [INFO] [stdout] 2025-10-02T04:48:54.205429Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=0 future=16 [INFO] [stdout] 2025-10-02T04:48:54.205444Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=0 future=16 [INFO] [stdout] 2025-10-02T04:48:54.205456Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=0 future=16 [INFO] [stdout] 2025-10-02T04:48:54.205468Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=0 future=16 [INFO] [stdout] 2025-10-02T04:48:54.205481Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=0 future=55 [INFO] [stdout] 2025-10-02T04:48:54.205493Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=0 future=39 [INFO] [stdout] 2025-10-02T04:48:54.205509Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.205521Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.205531Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.205578Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.205593Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.205603Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.205612Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.205619Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.205628Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.205638Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.205647Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.205657Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.205669Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.205677Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.205688Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.205698Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.205707Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.205717Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.205728Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.205736Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.205747Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.205758Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.205767Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.205777Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.205788Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.205796Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.205806Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.205817Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.205827Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.205837Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.205848Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.205857Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.205870Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.205881Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.205890Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.205900Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.205919Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.205928Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.205937Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.205948Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.205956Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.205965Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.205975Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.205983Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.205993Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.206003Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.206011Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.206021Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.206032Z DEBUG ramu_rs::controller: issue cmd cmd=RD clk=16 [INFO] [stdout] 2025-10-02T04:48:54.206041Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.206052Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.206064Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.206075Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.206089Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RD current=0 future=20 [INFO] [stdout] 2025-10-02T04:48:54.206118Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RDA current=0 future=20 [INFO] [stdout] 2025-10-02T04:48:54.206134Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RD current=0 future=20 [INFO] [stdout] 2025-10-02T04:48:54.206149Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RDA current=0 future=20 [INFO] [stdout] 2025-10-02T04:48:54.206162Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WR current=0 future=26 [INFO] [stdout] 2025-10-02T04:48:54.206176Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WRA current=0 future=26 [INFO] [stdout] 2025-10-02T04:48:54.206190Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PREA current=39 future=25 [INFO] [stdout] 2025-10-02T04:48:54.205082Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RDA current=0 future=21 [INFO] [stdout] 2025-10-02T04:48:54.206203Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PDE current=1 future=37 [INFO] [stdout] 2025-10-02T04:48:54.206220Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RD current=0 future=22 [INFO] [stdout] 2025-10-02T04:48:54.206234Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RDA current=0 future=22 [INFO] [stdout] 2025-10-02T04:48:54.206248Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=RD timing.cmd=PRE current=39 future=25 [INFO] [stdout] 2025-10-02T04:48:54.206263Z 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:54.206238Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RD current=0 future=21 [INFO] [stdout] 2025-10-02T04:48:54.200721Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7] [INFO] [stdout] 2025-10-02T04:48:54.206443Z  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:54.206486Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.206498Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.206509Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.206520Z  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:54.206534Z  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:54.206545Z  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:54.206557Z  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:54.206567Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.206578Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.206589Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.206599Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.206610Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.206620Z  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:54.206633Z  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:54.206645Z  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:54.206657Z  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:54.206672Z  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:54.206688Z  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:54.206703Z  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:54.206717Z  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:54.206729Z  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:54.206740Z  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:54.206754Z  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:54.206766Z  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:54.206780Z  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:54.206792Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.206803Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.206813Z  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:54.206825Z  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:54.206837Z  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:54.206848Z  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:54.206859Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.206876Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.206887Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.206897Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.206908Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.206919Z  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:54.206933Z  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:54.206945Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.206956Z  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:54.206968Z  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:54.206979Z  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:54.206994Z  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:54.207007Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.207018Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.207028Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.207039Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.207050Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.207060Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.207070Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.207081Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.207092Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.207102Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.207113Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.207124Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.207134Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.207144Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.207154Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.207164Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.207176Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.207186Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.207196Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.207206Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.207216Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.207226Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.207236Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.207246Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.207257Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.207267Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.207278Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.207288Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.207298Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-02T04:48:54.207308Z  INFO ramu_rs::ddr4: read_latency read_latency=20 [INFO] [stdout] 2025-10-02T04:48:54.207439Z DEBUG ramu_rs::test: addr_1=0 addr_2=8192 [INFO] [stdout] 2025-10-02T04:48:54.207454Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.207463Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.207474Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=1 [INFO] [stdout] 2025-10-02T04:48:54.207483Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.207494Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.207504Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.207514Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.207525Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.207537Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=0 future=1 [INFO] [stdout] 2025-10-02T04:48:54.207550Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=0 future=40 [INFO] [stdout] 2025-10-02T04:48:54.206282Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RDA current=0 future=21 [INFO] [stdout] 2025-10-02T04:48:54.207563Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=0 future=56 [INFO] [stdout] 2025-10-02T04:48:54.207575Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=0 future=2 [INFO] [stdout] 2025-10-02T04:48:54.207588Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=0 future=1 [INFO] [stdout] 2025-10-02T04:48:54.207601Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=0 future=17 [INFO] [stdout] 2025-10-02T04:48:54.207613Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=0 future=17 [INFO] [stdout] 2025-10-02T04:48:54.207625Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=0 future=17 [INFO] [stdout] 2025-10-02T04:48:54.207637Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=0 future=17 [INFO] [stdout] 2025-10-02T04:48:54.207649Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=0 future=56 [INFO] [stdout] 2025-10-02T04:48:54.207661Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=0 future=40 [INFO] [stdout] 2025-10-02T04:48:54.207676Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.207684Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.207693Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.207703Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.207710Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.207577Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WR current=0 future=27 [INFO] [stdout] 2025-10-02T04:48:54.207719Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.207729Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.207730Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WRA current=0 future=27 [INFO] [stdout] 2025-10-02T04:48:54.207738Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.207747Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.207745Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PREA current=40 future=26 [INFO] [stdout] 2025-10-02T04:48:54.207757Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.207758Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PDE current=2 future=38 [INFO] [stdout] 2025-10-02T04:48:54.207764Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.207773Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.207772Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RD current=0 future=23 [INFO] [stdout] 2025-10-02T04:48:54.207782Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.207785Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RDA current=0 future=23 [INFO] [stdout] 2025-10-02T04:48:54.207790Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.207799Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.207799Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=RD timing.cmd=PRE current=40 future=26 [INFO] [stdout] 2025-10-02T04:48:54.207808Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.207815Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.207814Z 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:54.207824Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.207829Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.207834Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.207838Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.207841Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.207850Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.207860Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.207868Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.207877Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.207887Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.207894Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.207903Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.207847Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.207913Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.207921Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.207922Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.207930Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.207933Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.207940Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.207941Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.207948Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.207951Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.207958Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.207959Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.207968Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.207969Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.207977Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.207980Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.207986Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.207988Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.207997Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.207997Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.208005Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.208007Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.208014Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.208019Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.208024Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.208032Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.208042Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.208052Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.208060Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.208029Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.208069Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.208075Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.208079Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.208085Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.208088Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.208097Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.208095Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.208107Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.208113Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.208115Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.208121Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.208125Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.208131Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.208135Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.208141Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.208143Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.208150Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.208152Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.208159Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.208162Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.208168Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.208172Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.208176Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.208182Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.208184Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.208191Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.208194Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.208199Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.208208Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.208218Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.208226Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.208202Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.208235Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.208245Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.208243Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.208252Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.208256Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.208262Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.208265Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.208273Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.208274Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.208280Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.208284Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.208289Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.208293Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.208300Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.208303Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.208308Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.208313Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.208318Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.208322Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.208328Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.208331Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.208336Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.208342Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.208418Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.208433Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.208428Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=17 future=72 [INFO] [stdout] 2025-10-02T04:48:54.208445Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.208454Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.208452Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=56 future=111 [INFO] [stdout] 2025-10-02T04:48:54.208463Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.208466Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=40 future=95 [INFO] [stdout] 2025-10-02T04:48:54.208474Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.208482Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.208484Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.208491Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.208494Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.208500Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.208503Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.208508Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.208514Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.208518Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.208522Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.208528Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.208533Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.208543Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.208551Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.208561Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.208537Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.208571Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.208578Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.208578Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.208587Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.208591Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.208598Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.208600Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.208606Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.208609Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.208615Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.208620Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.208625Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.208629Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.208633Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.208639Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.208642Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.208652Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.208656Z 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:54.208660Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.208667Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.208670Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.208676Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.208681Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.208686Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.208689Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.208697Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.208698Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.208705Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.208708Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.208716Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.208725Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.208735Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.208742Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.208752Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.208762Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.208770Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.208779Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.208789Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.208797Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.208806Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.208816Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.208824Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.208833Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.208843Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.208851Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.208860Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.208870Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.208878Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.208887Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.208920Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.209014Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.209045Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.209044Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.209056Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.209079Z DEBUG ramu_rs::controller: issue cmd cmd=WR clk=72 [INFO] [stdout] 2025-10-02T04:48:54.209089Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.209109Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.209120Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.209131Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2025-10-02T04:48:54.209144Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WR current=0 future=76 [INFO] [stdout] 2025-10-02T04:48:54.209158Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WRA current=0 future=76 [INFO] [stdout] 2025-10-02T04:48:54.209172Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WR current=27 future=76 [INFO] [stdout] 2025-10-02T04:48:54.209184Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WRA current=27 future=76 [INFO] [stdout] 2025-10-02T04:48:54.209198Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RD current=21 future=91 [INFO] [stdout] 2025-10-02T04:48:54.209211Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RDA current=21 future=91 [INFO] [stdout] 2025-10-02T04:48:54.209224Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PREA current=95 future=106 [INFO] [stdout] 2025-10-02T04:48:54.209237Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PDE current=57 future=106 [INFO] [stdout] 2025-10-02T04:48:54.209251Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WR current=0 future=78 [INFO] [stdout] 2025-10-02T04:48:54.209264Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WRA current=0 future=78 [INFO] [stdout] 2025-10-02T04:48:54.209262Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.209279Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RD current=23 future=97 [INFO] [stdout] 2025-10-02T04:48:54.209286Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.209292Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RDA current=23 future=97 [INFO] [stdout] 2025-10-02T04:48:54.209299Z DEBUG ramu_rs::controller: issue cmd cmd=PRE clk=40 [INFO] [stdout] 2025-10-02T04:48:54.209306Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=WR timing.cmd=PRE current=95 future=106 [INFO] [stdout] 2025-10-02T04:48:54.209309Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.209320Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.209327Z 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:54.209332Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.209338Z 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:54.209344Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2025-10-02T04:48:54.209357Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=REF current=56 future=56 [INFO] [stdout] 2025-10-02T04:48:54.209371Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=SRE current=0 future=56 [INFO] [stdout] 2025-10-02T04:48:54.209386Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=PRE timing.cmd=ACT current=56 future=56 [INFO] [stdout] test test::test_memory_read_and_write ... ok [INFO] [stdout] 2025-10-02T04:48:54.209402Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.209638Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.209653Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.209662Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.209672Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.209684Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.209694Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.209703Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.209714Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.209722Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.209732Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.209740Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.209750Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.209972Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.209994Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.210003Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.210014Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.210023Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.210033Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.210041Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.210051Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.210059Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.210069Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.210078Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.210089Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.210308Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.210331Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.210341Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.210352Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.210361Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.210371Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.210379Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.210391Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=56 [INFO] [stdout] 2025-10-02T04:48:54.210608Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.210629Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.210639Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.210649Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2025-10-02T04:48:54.210659Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.210669Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=1 future=56 [INFO] [stdout] 2025-10-02T04:48:54.210681Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=40 future=95 [INFO] [stdout] 2025-10-02T04:48:54.210693Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=56 future=111 [INFO] [stdout] 2025-10-02T04:48:54.210705Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=38 future=57 [INFO] [stdout] 2025-10-02T04:48:54.210718Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=1 future=56 [INFO] [stdout] 2025-10-02T04:48:54.210731Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=17 future=72 [INFO] [stdout] 2025-10-02T04:48:54.210743Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=17 future=72 [INFO] [stdout] 2025-10-02T04:48:54.210965Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=17 future=72 [INFO] [stdout] 2025-10-02T04:48:54.210984Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=17 future=72 [INFO] [stdout] 2025-10-02T04:48:54.210998Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=56 future=111 [INFO] [stdout] 2025-10-02T04:48:54.211010Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=40 future=95 [INFO] [stdout] 2025-10-02T04:48:54.211027Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.211036Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.211046Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.211057Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.211068Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.211077Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.211087Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.211321Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.211333Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.211345Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.211354Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.211363Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.211373Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.211380Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.211389Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.208368Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.211399Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.211441Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.211451Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.211459Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.211463Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.211470Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.211474Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.211481Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.211483Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.211489Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.211492Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.211499Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.211503Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.211509Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.211511Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.211517Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.211521Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.211527Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.211531Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.211537Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.211539Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.211546Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.211549Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.211555Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.211559Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.211565Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.211567Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.211573Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.211577Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.211582Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.211808Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.211814Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.211824Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.211827Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-02T04:48:54.211834Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.211836Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.211844Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.211847Z DEBUG ramu_rs::controller: issue cmd cmd=WR clk=17 [INFO] [stdout] 2025-10-02T04:48:54.211852Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.211857Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.211862Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.211868Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.211872Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.211879Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.211884Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.211890Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.211893Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.211904Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.211903Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WR current=0 future=21 [INFO] [stdout] 2025-10-02T04:48:54.211912Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.211916Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WRA current=0 future=21 [INFO] [stdout] 2025-10-02T04:48:54.211922Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.211930Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WR current=0 future=21 [INFO] [stdout] 2025-10-02T04:48:54.211943Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WRA current=0 future=21 [INFO] [stdout] 2025-10-02T04:48:54.211955Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RD current=0 future=36 [INFO] [stdout] 2025-10-02T04:48:54.211967Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RDA current=0 future=36 [INFO] [stdout] 2025-10-02T04:48:54.211979Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PREA current=40 future=51 [INFO] [stdout] 2025-10-02T04:48:54.211992Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PDE current=2 future=51 [INFO] [stdout] 2025-10-02T04:48:54.212006Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WR current=0 future=23 [INFO] [stdout] 2025-10-02T04:48:54.212018Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WRA current=0 future=23 [INFO] [stdout] 2025-10-02T04:48:54.212031Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RD current=0 future=42 [INFO] [stdout] 2025-10-02T04:48:54.212044Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RDA current=0 future=42 [INFO] [stdout] 2025-10-02T04:48:54.212057Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=WR timing.cmd=PRE current=40 future=51 [INFO] [stdout] 2025-10-02T04:48:54.212074Z 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:54.212096Z 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:54.212107Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.212115Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.212125Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.212136Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.212144Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.212153Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.212162Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.212171Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.212180Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.212190Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.212198Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.212207Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.212218Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.212226Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.212235Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.212245Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.212253Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.212262Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.212272Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.212280Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.212289Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.212299Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.212306Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.212316Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.212327Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.212336Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.212354Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.212364Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.212373Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.212382Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.212392Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.212400Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.212425Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.212437Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.212434Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.212445Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.212454Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.212454Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.212465Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.212466Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.212473Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.212479Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-02T04:48:54.212483Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.212488Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.212492Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.212498Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-02T04:48:54.212501Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.212510Z DEBUG ramu_rs::controller: issue cmd cmd=RD clk=72 [INFO] [stdout] 2025-10-02T04:48:54.212510Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.212521Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.212520Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.212530Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.212532Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.212541Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.212544Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.212551Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.212555Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2025-10-02T04:48:54.212560Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.212569Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.212579Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.212587Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.212596Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.212568Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RD current=21 future=76 [INFO] [stdout] 2025-10-02T04:48:54.212606Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.212614Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.212613Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RDA current=21 future=76 [INFO] [stdout] 2025-10-02T04:48:54.212623Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.212632Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.212629Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RD current=21 future=76 [INFO] [stdout] 2025-10-02T04:48:54.212640Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.212649Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.212659Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.212668Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.212676Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.212686Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.212694Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.212703Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.212714Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.212722Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.212732Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.212742Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.212749Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.212759Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.212769Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.212777Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.212786Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.212796Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.212805Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.212814Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.212824Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.212832Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.212841Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.212851Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.212860Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.212869Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.212878Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.212886Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.212895Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.212905Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.212915Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.212927Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.212940Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.212948Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.212957Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.212967Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.212977Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.212986Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.212996Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.213004Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.213014Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.213024Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.213032Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.213041Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.213052Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.213060Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.213069Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-02T04:48:54.213080Z DEBUG ramu_rs::controller: issue cmd cmd=PRE clk=51 [INFO] [stdout] 2025-10-02T04:48:54.213089Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.213101Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.213111Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.213122Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2025-10-02T04:48:54.213135Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=REF current=56 future=67 [INFO] [stdout] 2025-10-02T04:48:54.213149Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=SRE current=0 future=67 [INFO] [stdout] 2025-10-02T04:48:54.213163Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=PRE timing.cmd=ACT current=56 future=67 [INFO] [stdout] 2025-10-02T04:48:54.213177Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.213186Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.213196Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.213204Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.213214Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.213222Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.213233Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.213241Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.213251Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.213259Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.213269Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.213277Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.213288Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.213296Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.213305Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.213313Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.213323Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.213331Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.213341Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.213357Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.213367Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.213375Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.213392Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.213401Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.213427Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.213436Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.213447Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.213455Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.213465Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.213473Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.213483Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.213491Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-02T04:48:54.213502Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=67 [INFO] [stdout] 2025-10-02T04:48:54.213512Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.213523Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.213534Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.213544Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2025-10-02T04:48:54.213556Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.213566Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=1 future=67 [INFO] [stdout] 2025-10-02T04:48:54.213579Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=51 future=106 [INFO] [stdout] 2025-10-02T04:48:54.213592Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=67 future=122 [INFO] [stdout] 2025-10-02T04:48:54.213605Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=51 future=68 [INFO] [stdout] 2025-10-02T04:48:54.213618Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=1 future=67 [INFO] [stdout] 2025-10-02T04:48:54.213632Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=17 future=83 [INFO] [stdout] 2025-10-02T04:48:54.213645Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=17 future=83 [INFO] [stdout] 2025-10-02T04:48:54.213658Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=17 future=83 [INFO] [stdout] 2025-10-02T04:48:54.213671Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=17 future=83 [INFO] [stdout] 2025-10-02T04:48:54.213683Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=67 future=122 [INFO] [stdout] 2025-10-02T04:48:54.213696Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=51 future=106 [INFO] [stdout] 2025-10-02T04:48:54.213712Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.213720Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.213730Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.213740Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.213748Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.213758Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.213768Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.213777Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.213786Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.213797Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.213804Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.213813Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.213823Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.213831Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.213840Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.213850Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.213858Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.213868Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.213877Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.213885Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.213894Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.213904Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.213913Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.213922Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.213932Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.213939Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.213948Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.213958Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.213966Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.213976Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.213986Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.213994Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.214003Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.214013Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.214021Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.214030Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.214041Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.214049Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.214058Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.214068Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.214076Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.214085Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.214095Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.214103Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.214113Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.214123Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-02T04:48:54.214131Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-02T04:48:54.214140Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-02T04:48:54.214150Z DEBUG ramu_rs::controller: issue cmd cmd=WR clk=83 [INFO] [stdout] 2025-10-02T04:48:54.214159Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.214169Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.214180Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-10-02T04:48:54.214191Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2025-10-02T04:48:54.214204Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WR current=21 future=87 [INFO] [stdout] 2025-10-02T04:48:54.214216Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WRA current=21 future=87 [INFO] [stdout] 2025-10-02T04:48:54.214230Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WR current=21 future=87 [INFO] [stdout] 2025-10-02T04:48:54.214242Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WRA current=21 future=87 [INFO] [stdout] 2025-10-02T04:48:54.216508Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RD current=36 future=102 [INFO] [stdout] 2025-10-02T04:48:54.216530Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RDA current=36 future=102 [INFO] [stdout] 2025-10-02T04:48:54.219432Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PREA current=106 future=117 [INFO] [stdout] 2025-10-02T04:48:54.219463Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PDE current=68 future=117 [INFO] [stdout] 2025-10-02T04:48:54.219478Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WR current=23 future=89 [INFO] [stdout] 2025-10-02T04:48:54.219490Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WRA current=23 future=89 [INFO] [stdout] 2025-10-02T04:48:54.219503Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RD current=42 future=108 [INFO] [stdout] 2025-10-02T04:48:54.219515Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RDA current=42 future=108 [INFO] [stdout] 2025-10-02T04:48:54.219527Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=WR timing.cmd=PRE current=106 future=117 [INFO] [stdout] 2025-10-02T04:48:54.219544Z 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:54.219559Z 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] 2025-10-02T04:48:54.212643Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RDA current=21 future=76 [INFO] [stderr] error: test failed, to rerun pass `--lib` [INFO] [stdout] 2025-10-02T04:48:54.241867Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WR current=27 future=82 [INFO] [stdout] 2025-10-02T04:48:54.241903Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WRA current=27 future=82 [INFO] [stdout] 2025-10-02T04:48:54.241919Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PREA current=95 future=81 [INFO] [stdout] 2025-10-02T04:48:54.241943Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PDE current=57 future=93 [INFO] [stdout] 2025-10-02T04:48:54.241975Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RD current=23 future=78 [INFO] [stdout] 2025-10-02T04:48:54.241991Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RDA current=23 future=78 [INFO] [stdout] 2025-10-02T04:48:54.242006Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=RD timing.cmd=PRE current=95 future=81 [INFO] [stdout] 2025-10-02T04:48:54.242026Z 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:54.242062Z 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] [INFO] [stdout] failures: [INFO] [stdout] [INFO] [stdout] ---- controller::tests::test_controller_simple_read stdout ---- [INFO] [stdout] Failed to init tracing: a global default trace dispatcher has already been set [INFO] [stdout] [INFO] [stdout] thread 'controller::tests::test_controller_simple_read' (25) panicked at src/controller.rs:300:9: [INFO] [stdout] assertion failed: controller.finished_queue.is_empty() [INFO] [stdout] stack backtrace: [INFO] [stdout] 0: 0x5d224eef4602 - std::backtrace_rs::backtrace::libunwind::trace::hc4a5f428cfb78751 [INFO] [stdout] at /rustc/b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b/library/std/src/../../backtrace/src/backtrace/libunwind.rs:117:9 [INFO] [stdout] 1: 0x5d224eef4602 - std::backtrace_rs::backtrace::trace_unsynchronized::h20e1095684b4c296 [INFO] [stdout] at /rustc/b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b/library/std/src/../../backtrace/src/backtrace/mod.rs:66:14 [INFO] [stdout] 2: 0x5d224eef4602 - std::sys::backtrace::_print_fmt::h461f2e3a8f6b29e2 [INFO] [stdout] at /rustc/b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b/library/std/src/sys/backtrace.rs:66:9 [INFO] [stdout] 3: 0x5d224eef4602 - ::fmt::h4ee3a75aa71a2c45 [INFO] [stdout] at /rustc/b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b/library/std/src/sys/backtrace.rs:39:26 [INFO] [stdout] 4: 0x5d224ef17aff - core::fmt::rt::Argument::fmt::h6f1564705cd089af [INFO] [stdout] at /rustc/b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b/library/core/src/fmt/rt.rs:173:76 [INFO] [stdout] 5: 0x5d224ef17aff - core::fmt::write::h21ca93b65a7c281a [INFO] [stdout] at /rustc/b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b/library/core/src/fmt/mod.rs:1468:25 [INFO] [stdout] 6: 0x5d224eee1393 - std::io::default_write_fmt::h6f3360f4711e9130 [INFO] [stdout] at /rustc/b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b/library/std/src/io/mod.rs:639:11 [INFO] [stdout] 7: 0x5d224eee1393 - std::io::Write::write_fmt::hf4539125c0e0bc30 [INFO] [stdout] at /rustc/b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b/library/std/src/io/mod.rs:1954:13 [INFO] [stdout] 8: 0x5d224eef4c52 - std::sys::backtrace::BacktraceLock::print::h58d5d73f9e953cf1 [INFO] [stdout] at /rustc/b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b/library/std/src/sys/backtrace.rs:42:9 [INFO] [stdout] 9: 0x5d224eedf8fc - std::panicking::default_hook::{{closure}}::h1457fbe47c9457d1 [INFO] [stdout] at /rustc/b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b/library/std/src/panicking.rs:301:27 [INFO] [stdout] 10: 0x5d224eedf774 - std::panicking::default_hook::hccb5e73b206c0830 [INFO] [stdout] at /rustc/b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b/library/std/src/panicking.rs:325:9 [INFO] [stdout] 11: 0x5d224ece242e - as core::ops::function::Fn>::call::h04940a86aa899793 [INFO] [stdout] at /rustc/b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b/library/alloc/src/boxed.rs:1985:9 [INFO] [stdout] 12: 0x5d224ece242e - test::test_main_with_exit_callback::{{closure}}::hca6cc295403b83e8 [INFO] [stdout] at /rustc/b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b/library/test/src/lib.rs:145:21 [INFO] [stdout] 13: 0x5d224eee05a3 - as core::ops::function::Fn>::call::h9d85285925beb538 [INFO] [stdout] at /rustc/b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b/library/alloc/src/boxed.rs:1985:9 [INFO] [stdout] 14: 0x5d224eee05a3 - std::panicking::panic_with_hook::h3190ecc6229cdd29 [INFO] [stdout] at /rustc/b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b/library/std/src/panicking.rs:842:13 [INFO] [stdout] 15: 0x5d224eef4a26 - std::panicking::panic_handler::{{closure}}::ha1f1b769bc2bb40c [INFO] [stdout] at /rustc/b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b/library/std/src/panicking.rs:700:13 [INFO] [stdout] 16: 0x5d224eef49b9 - std::sys::backtrace::__rust_end_short_backtrace::h5f9cf66f19c2a172 [INFO] [stdout] at /rustc/b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b/library/std/src/sys/backtrace.rs:174:18 [INFO] [stdout] 17: 0x5d224eee01fd - __rustc[a93bd50104b99ad4]::rust_begin_unwind [INFO] [stdout] at /rustc/b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b/library/std/src/panicking.rs:698:5 [INFO] [stdout] 18: 0x5d224ef204a0 - core::panicking::panic_fmt::hc70c3c83f13c1375 [INFO] [stdout] at /rustc/b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b/library/core/src/panicking.rs:75:14 [INFO] [stdout] 19: 0x5d224ef207dc - core::panicking::panic::h413ab907c3df10e0 [INFO] [stdout] at /rustc/b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b/library/core/src/panicking.rs:145:5 [INFO] [stdout] 20: 0x5d224ecbb3ff - ramu_rs::controller::tests::test_controller_simple_read::hd1bff95b0137f553 [INFO] [stdout] at /opt/rustwide/workdir/src/controller.rs:300:9 [INFO] [stdout] 21: 0x5d224ecbb507 - ramu_rs::controller::tests::test_controller_simple_read::{{closure}}::hbffb5d3754060597 [INFO] [stdout] at /opt/rustwide/workdir/src/controller.rs:277:37 [INFO] [stdout] 22: 0x5d224ecb6766 - core::ops::function::FnOnce::call_once::hca9ec7329ed833f3 [INFO] [stdout] at /rustc/b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b/library/core/src/ops/function.rs:253:5 [INFO] [stdout] 23: 0x5d224ece34ab - core::ops::function::FnOnce::call_once::h70d190c46966003b [INFO] [stdout] at /rustc/b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b/library/core/src/ops/function.rs:253:5 [INFO] [stdout] 24: 0x5d224ece34ab - test::__rust_begin_short_backtrace::hb077ccaabb17d2ec [INFO] [stdout] at /rustc/b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b/library/test/src/lib.rs:663:18 [INFO] [stdout] 25: 0x5d224ece1115 - test::run_test_in_process::{{closure}}::hd73eeb633a1507bd [INFO] [stdout] at /rustc/b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b/library/test/src/lib.rs:686:74 [INFO] [stdout] 26: 0x5d224ece1115 - as core::ops::function::FnOnce<()>>::call_once::h033c82756fc9d192 [INFO] [stdout] at /rustc/b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b/library/core/src/panic/unwind_safe.rs:272:9 [INFO] [stdout] 27: 0x5d224ece1115 - std::panicking::catch_unwind::do_call::h734b44e243d34585 [INFO] [stdout] at /rustc/b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b/library/std/src/panicking.rs:590:40 [INFO] [stdout] 28: 0x5d224ece1115 - std::panicking::catch_unwind::h5e85417122517fb1 [INFO] [stdout] at /rustc/b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b/library/std/src/panicking.rs:553:19 [INFO] [stdout] 29: 0x5d224ece1115 - std::panic::catch_unwind::h0900e58a82a7d188 [INFO] [stdout] at /rustc/b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b/library/std/src/panic.rs:359:14 [INFO] [stdout] 30: 0x5d224ece1115 - test::run_test_in_process::h27721efd62ae77d0 [INFO] [stdout] at /rustc/b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b/library/test/src/lib.rs:686:27 [INFO] [stdout] 31: 0x5d224ece1115 - test::run_test::{{closure}}::h8b1264838cc597aa [INFO] [stdout] at /rustc/b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b/library/test/src/lib.rs:607:43 [INFO] [stdout] 32: 0x5d224ed08024 - test::run_test::{{closure}}::h6ecb96835e2eae4f [INFO] [stdout] at /rustc/b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b/library/test/src/lib.rs:637:41 [INFO] [stdout] 33: 0x5d224ed08024 - std::sys::backtrace::__rust_begin_short_backtrace::h098f38ee82a820a7 [INFO] [stdout] at /rustc/b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b/library/std/src/sys/backtrace.rs:158:18 [INFO] [stdout] 34: 0x5d224eceec3a - std::thread::Builder::spawn_unchecked_::{{closure}}::{{closure}}::h042592f748f5e369 [INFO] [stdout] at /rustc/b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b/library/std/src/thread/mod.rs:559:17 [INFO] [stdout] 35: 0x5d224eceec3a - as core::ops::function::FnOnce<()>>::call_once::h134fe7f3a2d9ec8d [INFO] [stdout] at /rustc/b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b/library/core/src/panic/unwind_safe.rs:272:9 [INFO] [stdout] 36: 0x5d224eceec3a - std::panicking::catch_unwind::do_call::heb87d604f60aee16 [INFO] [stdout] at /rustc/b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b/library/std/src/panicking.rs:590:40 [INFO] [stdout] 37: 0x5d224eceec3a - std::panicking::catch_unwind::h2203a0f553b89fd7 [INFO] [stdout] at /rustc/b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b/library/std/src/panicking.rs:553:19 [INFO] [stdout] 38: 0x5d224eceec3a - std::panic::catch_unwind::h4d383e0b0e25d838 [INFO] [stdout] at /rustc/b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b/library/std/src/panic.rs:359:14 [INFO] [stdout] 39: 0x5d224eceec3a - std::thread::Builder::spawn_unchecked_::{{closure}}::h76cbdd4635cfd58b [INFO] [stdout] at /rustc/b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b/library/std/src/thread/mod.rs:557:30 [INFO] [stdout] 40: 0x5d224eceec3a - core::ops::function::FnOnce::call_once{{vtable.shim}}::he72e066680f5e267 [INFO] [stdout] at /rustc/b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b/library/core/src/ops/function.rs:253:5 [INFO] [stdout] 41: 0x5d224eecb02f - as core::ops::function::FnOnce>::call_once::h1b9c6fea2cbefc68 [INFO] [stdout] at /rustc/b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b/library/alloc/src/boxed.rs:1971:9 [INFO] [stdout] 42: 0x5d224eecb02f - std::sys::pal::unix::thread::Thread::new::thread_start::h92caa992bc760789 [INFO] [stdout] at /rustc/b6ae10aa7319b7ebb6c7b3331dd71a9d6c9c5b4b/library/std/src/sys/pal/unix/thread.rs:107:17 [INFO] [stdout] 43: 0x7a0a17920aa4 - [INFO] [stdout] 44: 0x7a0a179ada34 - clone [INFO] [stdout] 45: 0x0 - [INFO] [stdout] [INFO] [stdout] [INFO] [stdout] failures: [INFO] [stdout] controller::tests::test_controller_simple_read [INFO] [stdout] [INFO] [stdout] test result: FAILED. 6 passed; 1 failed; 1 ignored; 0 measured; 0 filtered out; finished in 0.05s [INFO] [stdout] [INFO] running `Command { std: "docker" "inspect" "ffec98defbf27d28e40b9500f548b9ecf00e9e51cdefb547a17dbfadddc7912c", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "ffec98defbf27d28e40b9500f548b9ecf00e9e51cdefb547a17dbfadddc7912c", kill_on_drop: false }` [INFO] [stdout] ffec98defbf27d28e40b9500f548b9ecf00e9e51cdefb547a17dbfadddc7912c