Re: RPi4B "C0T" (Rev 1.5) part and the duplicate/diff/cmp huge file test for UEFI/ACPI contexts: fails far worse than past B0T testing did

On Nov 28, 2022, at 23:35, Mark Millard <[email protected]> wrote:

> [Summary: using a kernel with my historical patching
> did not avoid such failures.]
> 
> On Nov 28, 2022, at 22:37, Mark Millard <[email protected]> wrote:
> 
>> FreeBSD has never updated the ACPI support to deal with
>> the DMA limitations of the B0T RPi4B parts, here the
>> xhci related limitation to the lower 3 GiBytes. This was
>> a test do see what a C0T RPi4B ends up with for behavior
>> based on the not-adjusted code.
>> 
>> Boot media prepared on a HoneyComb with snapshot (long line split
>> for readability):
>> 
>> FreeBSD 13.1-STABLE #0 stable/13-n253133-b51ee7ac252c: Wed Nov 23 03:36:16 UTC 2022
>> [email protected]:/usr/obj/usr/src/arm64.aarch64/sys/GENERIC
>> 
>> (so, not my build). But I replaced the U-Boot/RPi*-firmware
>> material with the material for ACPI use (via
>> /pftf/RPi4/releases/download/v1.33/RPi4_UEFI_Firmware_v1.33.zip
>> and my usual adjustments):
>> 
>> # ls -Tlat /mnt/
>> total 4401
>> drwxr-xr-x   1 root  wheel     4096 Nov 28 21:17:26 2022 normal_material_moved_here
>> -rwxr-xr-x   1 root  wheel      952 Sep 28 10:24:32 2022 config.txt
>> -rwxr-xr-x   1 root  wheel      952 Sep 28 10:24:32 2022 config.txt.uefi_m_m_fbsd
>> drwxr-xr-x   1 root  wheel     4096 Jun 28 20:47:10 2022 EFI
>> drwxr-xr-x   1 root  wheel     4096 Apr  4 00:51:20 2022 firmware
>> drwxr-xr-x   1 root  wheel     4096 Apr  4 00:51:20 2022 overlays
>> -rwxr-xr-x   1 root  wheel    51543 Mar  7 09:06:24 2022 bcm2711-rpi-4-b.dtb
>> -rwxr-xr-x   1 root  wheel    51675 Mar  7 09:06:24 2022 bcm2711-rpi-400.dtb
>> -rwxr-xr-x   1 root  wheel    52128 Mar  7 09:06:24 2022 bcm2711-rpi-cm4.dtb
>> -rwxr-xr-x   1 root  wheel  2241376 Mar  7 09:06:24 2022 start4.elf
>> -rwxr-xr-x   1 root  wheel     5352 Mar  7 09:06:22 2022 fixup4.dat
>> drwxr-xr-x  58 root  wheel       65 Mar  7 09:04:04 2022 ..
>> -rwxr-xr-x   1 root  wheel  2031616 Mar  7 09:03:46 2022 RPI_EFI.fd
>> -rwxr-xr-x   1 root  wheel     5067 Mar  7 08:57:38 2022 Readme.md
>> -rwxr-xr-x   1 root  wheel      230 Mar  7 08:57:38 2022 config.txt.uefi_rpi4_orig
>> -rwxr-xr-x   1 root  wheel        0 Sep 13 14:15:28 2020 timeout
>> drwxr-xr-x   1 root  wheel    16384 Dec 31 16:00:00 1979 .
>> 
>> Also I had put in place for the duplicate and diff/cmp
>> test use the large file in the below:
>> 
>> # ls -Tlat
>> total 27064356
>> drwxr-xr-x   2 root  wheel          512 Nov 29 05:23:24 2022 .
>> -rw-------   1 root  wheel         1498 Nov 29 05:23:24 2022 .sh_history
>> -rw-------   1 root  wheel          163 Nov 29 04:12:52 2022 .history
>> -rw-r--r--   1 root  wheel         1191 Nov 29 04:11:02 2022 .shrc
>> -rw-r--r--   1 root  wheel  27707039744 Nov 28 19:11:23 2022 larger-than-RAM.tar
>> -rw-r--r--   1 root  wheel          328 Nov 23 04:07:48 2022 .login
>> -rw-r--r--   2 root  wheel         1023 Nov 23 04:07:48 2022 .cshrc
>> -rw-r--r--   2 root  wheel          507 Nov 23 04:07:48 2022 .profile
>> -rw-r--r--   1 root  wheel           80 Nov 23 04:07:38 2022 .k5login
>> drwxr-xr-x  20 root  wheel          512 Mar  7 17:03:52 2022 ..
>> 
>> Then I booted it on the C0T RPi4B and did the test after
>> logging in. The result was:
>> 
>> # cp -aRx larger-than-RAM.tar larger-than-RAM.tar.copied_via_RPi4B_C0T_Rev_1.5
>> xhci_interrupt: host system error
>> xhci_interrupt: host controller halted
>> xhci_interrupt: host system error
>> xhci0: Resetting controller
>> uhub1: at usbus1, port 1, addr 1 (disconnected)
>> ugen1.2: <vendor 0x2109 USB2.0 Hub> at usbus1 (disconnected)
>> uhub2: at uhub1, port 1, addr 1 (disconnected)
>> uhub2: detached
>> ugen1.3: <OWC Envoy Pro mini> at usbus1 (disconnected)
>> umass0: at uhub1, port 2, addr 2 (disconnected)
>> (da0:umass-sim0:0:0:0): WRITE(10). CDB: 2a 00 07 95 8a 40 00 08 00 00 
>> (da0:umass-sim0:0:0:0): CAM status: CCB request completed with an error
>> (da0:umass-sim0:0:0:0): Retrying command, 3 more tries remain
>> da0 at umass-sim0 bus 0 scbus0 target 0 lun 0
>> da0: <OWC Envoy Pro mini 0>  s/n 000000000014 detached
>> g_vfs_done():ufs/rootfs[WRITE(offset=65094778880, length=1048576)]error = 6
>> UFS: forcibly unmounting /dev/ufs/rootfs from /
>> g_vfs_done():ufs/rootfs[WRITE(offset=65095827456, length=1048576)]error = 6
>> . . .
>> g_vfs_done():ufs/rootfs[WRITE(offset=65088946176, length=589824)]error = 6
>> g_vfs_done():ufs/rootfs[WRITE(offset=65093730304, length=1048576)]error = 6
>> larger-than-RAM.tar: Device not configured
>> pid 668 (sh), jid 0, uid 0: exited on signal 4
>> pid 365 (devd), jid 0, uid 0: exited on signal 4
>> (da0:umass-sim0:0:0:0): Periph destroyed
>> pid 667 (login), jid 0, uid 0: exited on signal 4
>> umass0: detached
>> uhub1: detached
>> uhub1 on usbus1
>> uhub1: <Generic XHCI root HUB, class 9/0, rev 3.00/1.00, addr 1> on usbus1
>> uhub1: 5 ports with 4 removable, self powered
>> ugen1.2: <vendor 0x2109 USB2.0 Hub> at usbus1
>> uhub2 on uhub1
>> uhub2: <vendor 0x2109 USB2.0 Hub, class 9/0, rev 2.10/4.21, addr 1> on usbus1
>> uhub2: 4 ports with 4 removable, self powered
>> usb_msc_auto_quirk: UQ_MSC_NO_GETMAXLUN set for USB mass storage device OWC Envoy Pro mini (0x1e91:0xa2a5)
>> ugen1.3: <OWC Envoy Pro mini> at usbus1
>> umass0 on uhub1
>> umass0: <OWC Envoy Pro mini, class 0/0, rev 3.00/1.00, addr 2> on usbus1
>> umass0:  SCSI over Bulk-Only; quirks = 0x0100
>> umass0:0:0: Attached to scbus0
>> da0 at umass-sim0 bus 0 scbus0 target 0 lun 0
>> da0: <OWC Envoy Pro mini 0> Fixed Direct Access SPC-4 SCSI device
>> da0: Serial Number ***REDACTED***
>> da0: 400.000MB/s transfers
>> da0: 228936MB (468862128 512 byte sectors)
>> da0: quirks=0x2<NO_6_BYTE>
>> pid 637 (cron), jid 0, uid 0: exited on signal 4
>> 
>> 
>> That was all the output before things were hung up.
>> 
>> The old B0T testing got some corrupted blocks in 
>> the file copy(ies) in such testing but ran to
>> completion. But I've not run such tests in some
>> time.
>> 
>> I may see if my currently somewhat older but patched
>> kernel has problems as well for C0T RPi4B's, presuming 
>> ufficient world compatibility to leave the rest alone.
>> (I've never had problems with the patched kernel
>> versions on the B0T RPi4B's.)
> 
> This is for the older but patched kernel, as reported
> in:
> 
> # uname -apKU
> FreeBSD generic 13.1-STABLE FreeBSD 13.1-STABLE #43 stable/13-n252944-e52aaa644ce1-dirty: Mon Nov  7 09:55:56 PST 2022     root@CA72_16Gp_ZFS:/usr/obj/BUILDs/13S-CA72-nodbg-clang/usr/13S-src/arm64.aarch64/sys/GENERIC-NODBG-CA72 arm64 aarch64 1301509 1301509
> 
> Same sort of result using a "C0T" RPi4B:
> 
> # cp -aRx larger-than-RAM.tar larger-than-RAM.tar.copied_via_RPi4B_C0T_Rev_1.5
> xhci_interrupt: host system error
> xhci0: Resetting controller
> uhub0: at usbus1, port 1, addr 1 (disconnected)
> ugen1.2: <vendor 0x2109 USB2.0 Hub> at usbus1 (disconnected)
> uhub2: at uhub0, port 1, addr 1 (disconnected)
> uhub2: detached
> ugen1.3: <OWC Envoy Pro mini> at usbus1 (disconnected)
> umass0: at uhub0, port 3, addr 2 (disconnected)
> (da0:umass-sim0:0:0:0): WRITE(10). CDB: 2a 00 07 0e ee 40 00 08 00 00 
> (da0:umass-sim0:0:0:0): CAM status: CCB request completed with an error
> (da0:umass-sim0:0:0:0): Retrying command, 3 more tries remain
> da0 at umass-sim0 bus 0 scbus0 target 0 lun 0
> da0: <OWC Envoy Pro mini 0>  s/n 000000000014 detached
> g_vfs_done():ufs/rootfs[WRITE(offset=60578037760, length=1048576)]error = 6
> UFS: forcibly unmounting /dev/ufs/rootfs from /
> g_vfs_done():ufs/rootfs[WRITE(offset=60579086336, length=1048576)]error = 6
> g_vfs_done():ufs/rootfs[WRITE(offset=60580134912, length=1048576)]error = 6
> g_vfs_done():ufs/rootfs[WRITE(offset=60581183488, length=1048576)]error = 6
> g_vfs_done():ufs/rootfs[WRITE(offset=60582232064, length=1048576)]error = 6
> g_vfs_done():ufs/rootfs[WRITE(offset=60583280640, length=1048576)]error = 6
> g_vfs_done():ufs/rootfs[WRITE(offset=60584329216, length=1048576)]error = 6
> g_vfs_done():ufs/rootfs[WRITE(offset=60585377792, length=1048576)]error = 6
> g_vfs_done():ufs/rootfs[WRITE(offset=60586426368, length=1048576)]error = 6
> g_vfs_done():ufs/rootfs[WRITE(offset=60587474944, length=1048576)]error = 6
> g_vfs_done():ufs/rootfs[READ(offset=76881494016, length=32768)]error = 6
> g_vfs_done():ufs/rootfs[WRITE(offset=1806729216, length=12288)]error = 6
> g_vfs_done():ufs/rootfs[WRITE(offset=60576989184, length=1048576)]error = 6
> larger-than-RAM.tar: Device not configured
> pid 658 (sh), jid 0, uid 0: exited on signal 4
> (da0:umass-sim0:0:0:0): Periph destroyed
> pid 355 (devd), jid 0, uid 0: exited on signal 4
> umass0: detached
> pid 657 (login), jid 0, uid 0: exited on signal 4
> uhub0: detached
> uhub0 on usbus1
> uhub0: <Generic XHCI root HUB, class 9/0, rev 3.00/1.00, addr 1> on usbus1
> uhub0: 5 ports with 4 removable, self powered
> ugen1.2: <vendor 0x2109 USB2.0 Hub> at usbus1
> uhub2 on uhub0
> uhub2: <vendor 0x2109 USB2.0 Hub, class 9/0, rev 2.10/4.21, addr 1> on usbus1
> uhub2: 4 ports with 4 removable, self powered
> usb_msc_auto_quirk: UQ_MSC_NO_GETMAXLUN set for USB mass storage device OWC Envoy Pro mini (0x1e91:0xa2a5)
> ugen1.3: <OWC Envoy Pro mini> at usbus1
> umass0 on uhub0
> umass0: <OWC Envoy Pro mini, class 0/0, rev 3.00/1.00, addr 2> on usbus1
> umass0:  SCSI over Bulk-Only; quirks = 0x0100
> umass0:0:0: Attached to scbus0
> da0 at umass-sim0 bus 0 scbus0 target 0 lun 0
> da0: <OWC Envoy Pro mini 0> Fixed Direct Access SPC-4 SCSI device
> da0: Serial Number ***REDACTED***
> da0: 400.000MB/s transfers
> da0: 228936MB (468862128 512 byte sectors)
> da0: quirks=0x2<NO_6_BYTE>
> pid 627 (cron), jid 0, uid 0: exited on signal 4
> 
> 
> 
> So, after a fsck_ffs -y via the HoneyComb, trying
> on a "B0T" RPi4B got:
> 
> # cp -aRx larger-than-RAM.tar larger-than-RAM.tar.copied_via_RPi4B_B0T_Rev_1.4
> UFS /dev/ufs/rootfs (/) cylinder checksum failed: cg 92, cgp: 0x0 != bp: 0x43bc4552
> . . .
> UFS /dev/ufs/rootfs (/) cylinder checksum failed: cg 314, cgp: 0xffffffff != bp: 0x544dd2da

Even my patched-kernel + world from the same build
(no vintage mismatch) get such error messages when
mixed with UEFI/ACPI, even on a "B0T" RPi4B that
I've historically used.

Most of my historical use of UEFI/ACPI has been with ZFS
instead of UFS and with main instead of 13.1-STABLE,
unlike here for both, and most of it was before the added
cylinder related tests.

Looks like the cylinder tests may help detect some types
of I/O problems, possibly now exposing problems that were
silent before.

Looks like RPi4B EDK2 UEFI/ACPI should be avoided at this
point. I've reverted my use back to being U-Boot based.

> xhci_interrupt: host system error
> xhci0: Resetting controller
> uhub1: at usbus1, port 1, addr 1 (disconnected)
> ugen1.2: <vendor 0x2109 USB2.0 Hub> at usbus1 (disconnected)
> uhub2: at uhub1, port 1, addr 1 (disconnected)
> uhub2: detached
> ugen1.3: <OWC Envoy Pro mini> at usbus1 (disconnected)
> umass0: at uhub1, port 2, addr 2 (disconnected)
> (da0:umass-sim0:0:0:0): WRITE(10). CDB: 2a 00 16 84 d7 00 00 08 00 00 
> (da0:umass-sim0:0:0:0): CAM status: CCB request completed with an error
> (da0:umass-sim0:0:0:0): Retrying command, 3 more tries remain
> da0 at umass-sim0 bus 0 scbus0 target 0 lun 0
> da0: <OWC Envoy Pro mini 0>  s/n 000000000014 detached
> g_vfs_done():ufs/rootfs[WRITE(offset=193383432192, length=1048576)]error = 6
> UFS: forcibly unmounting /dev/ufs/rootfs from /
> g_vfs_done():ufs/rootfs[WRITE(offset=193384480768, length=1048576)]error = 6
> g_vfs_done():ufs/rootfs[WRITE(offset=193385529344, length=1048576)]error = 6
> g_vfs_done():ufs/rootfs[WRITE(offset=193386577920, length=1048576)]error = 6
> g_vfs_done():ufs/rootfs[WRITE(offset=193387626496, length=1048576)]error = 6
> g_vfs_done():ufs/rootfs[WRITE(offset=193388675072, length=1048576)]error = 6
> g_vfs_done():ufs/rootfs[WRITE(offset=193389723648, length=1048576)]error = 6
> g_vfs_done():ufs/rootfs[WRITE(offset=193390772224, length=1048576)]error = 6
> g_vfs_done():ufs/rootfs[WRITE(offset=193391820800, length=1048576)]error = 6
> g_vfs_done():ufs/rootfs[WRITE(offset=193392869376, length=1048576)]error = 6
> g_vfs_done():ufs/rootfs[WRITE(offset=193393917952, length=1048576)]error = 6
> g_vfs_done():ufs/rootfs[WRITE(offset=193394966528, length=1048576)]error = 6
> g_vfs_done():ufs/rootfs[WRITE(offset=193396015104, length=1048576)]error = 6
> g_vfs_done():ufs/rootfs[WRITE(offset=193397063680, length=1048576)]error = 6
> g_vfs_done():ufs/rootfs[WRITE(offset=193398112256, length=753664)]error = 6
> g_vfs_done():ufs/rootfs[WRITE(offset=1346174976, length=32768)]error = 6
> g_vfs_done():ufs/rootfs[WRITE(offset=1346207744, length=32768)]error = 6
> g_vfs_done():ufs/rootfs[WRITE(offset=1346240512, length=32768)]error = 6
> g_vfs_done():ufs/rootfs[WRITE(offset=1346273280, length=32768)]error = 6
> g_vfs_done():ufs/rootfs[WRITE(offset=1346306048, length=32768)]error = 6
> g_vfs_done():ufs/rootfs[WRITE(offset=1346338816, length=32768)]error = 6
> g_vfs_done():ufs/rootfs[WRITE(offset=1671835648, length=4096)]error = 6
> g_vfs_done():ufs/rootfs[WRITE(offset=1806696448, length=32768)]error = 6
> g_vfs_done():ufs/rootfs[WRITE(offset=1806827520, length=32768)]error = 6
> g_vfs_done():ufs/rootfs[WRITE(offset=1806860288, length=1048576)]error = 6
> g_vfs_done():ufs/rootfs[WRITE(offset=1807908864, length=425984)]error = 6
> g_vfs_done():ufs/rootfs[WRITE(offset=1808367616, length=1048576)]error = 6
> g_vfs_done():ufs/rootfs[WRITE(offset=1809416192, length=1048576)]error = 6
> g_vfs_done():ufs/rootfs[WRITE(offset=1810464768, length=1048576)]error = 6
> g_vfs_done():ufs/rootfs[WRITE(offset=1811513344, length=1048576)]error = 6
> g_vfs_done():ufs/rootfs[WRITE(offset=1812561920, length=1048576)]error = 6
> g_vfs_done():ufs/rootfs[WRITE(offset=1813610496, length=1048576)]error = 6
> g_vfs_done():ufs/rootfs[WRITE(offset=1814659072, length=950272)]error = 6
> g_vfs_done():ufs/rootfs[READ(offset=78798159872, length=32768)]error = 6
> g_vfs_done():ufs/rootfs[WRITE(offset=193332412416, length=1048576)]error = 6
> g_vfs_done():ufs/rootfs[WRITE(offset=193333460992, length=688128)]error = 6
> g_vfs_done():ufs/rootfs[WRITE(offset=193382383616, length=1048576)]error = 6
> larger-than-RAM.tar: Device not configured
> pid 658 (sh), jid 0, uid 0: exited on signal 4
> pid 355 (devd), jid 0, uid 0: exited on signal 4
> (da0:umass-sim0:0:0:0): Periph destroyed
> pid 657 (login), jid 0, uid 0: exited on signal 4
> umass0: detached
> uhub1: detached
> uhub1 on usbus1
> uhub1: <Generic XHCI root HUB, class 9/0, rev 3.00/1.00, addr 1> on usbus1
> uhub1: 5 ports with 4 removable, self powered
> ugen1.2: <vendor 0x2109 USB2.0 Hub> at usbus1
> uhub2 on uhub1
> uhub2: <vendor 0x2109 USB2.0 Hub, class 9/0, rev 2.10/4.21, addr 1> on usbus1
> uhub2: 4 ports with 4 removable, self powered
> usb_msc_auto_quirk: UQ_MSC_NO_GETMAXLUN set for USB mass storage device OWC Envoy Pro mini (0x1e91:0xa2a5)
> ugen1.3: <OWC Envoy Pro mini> at usbus1
> umass0 on uhub1
> umass0: <OWC Envoy Pro mini, class 0/0, rev 3.00/1.00, addr 2> on usbus1
> umass0:  SCSI over Bulk-Only; quirks = 0x0100
> umass0:0:0: Attached to scbus0
> da0 at umass-sim0 bus 0 scbus0 target 0 lun 0
> da0: <OWC Envoy Pro mini 0> Fixed Direct Access SPC-4 SCSI device
> da0: Serial Number ***REDACTED***
> da0: 400.000MB/s transfers
> da0: 228936MB (468862128 512 byte sectors)
> da0: quirks=0x2<NO_6_BYTE>
> pid 627 (cron), jid 0, uid 0: exited on signal 4
> 
> 
> The attempted fsck_ffs -y via teh HoneyComb got:
> 
> # fsck_ffs -y /dev/da0s2a
> ** /dev/da0s2a
> ** Last Mounted on /
> ** Phase 1 - Check Blocks and Sizes
> UFS2 cylinder group 2 failed: cgp->cg_ckhash ("4294967295") != calchash ("1414386394")
> UFS2 cylinder group 2 failed: cg_chkmagic(cgp) ("0") == 0 ("0")
> UFS2 cylinder group 2 failed: cgp->cg_cgx ("4294967295") != cg ("2")
> UFS2 cylinder group 2 failed: cgp->cg_ndblk ("4294967295") > sblock.fs_fpg ("160056")
> UFS2 cylinder group 2 failed: cgp->cg_niblk ("4294967295") != sblock.fs_ipg ("80128")
> UFS2 cylinder group 2 failed: cgp->cg_initediblk ("4294967295") > sblock.fs_ipg ("80128")
> CYLINDER GROUP 2: INTEGRITY CHECK FAILED
> UNEXPECTED SOFT UPDATE INCONSISTENCY
> 
> REBUILD CYLINDER GROUP? yes
> 
> INCORRECT BLOCK COUNT I=172606 (1136576 should be 262976)
> CORRECT? yes
> 
> INODE 172606: FILE SIZE 581730304 BEYOND END OF ALLOCATED FILE, SIZE SHOULD BE 134610944
> ADJUST? yes
> 
> CYLINDER GROUP 2: FOUND 12416 VALID INODES
> UFS2 cylinder group 86 failed: cgp->cg_ckhash ("4294967295") != calchash ("1414386394")
> UFS2 cylinder group 86 failed: cg_chkmagic(cgp) ("0") == 0 ("0")
> UFS2 cylinder group 86 failed: cgp->cg_cgx ("4294967295") != cg ("86")
> UFS2 cylinder group 86 failed: cgp->cg_ndblk ("4294967295") > sblock.fs_fpg ("160056")
> UFS2 cylinder group 86 failed: cgp->cg_niblk ("4294967295") != sblock.fs_ipg ("80128")
> UFS2 cylinder group 86 failed: cgp->cg_initediblk ("4294967295") > sblock.fs_ipg ("80128")
> CYLINDER GROUP 86: INTEGRITY CHECK FAILED
> UNEXPECTED SOFT UPDATE INCONSISTENCY
> 
> REBUILD CYLINDER GROUP? yes
> 
> INODE CHECK-HASH FAILED I=6891264  OWNER=1746441326 MODE=146121
> SIZE=10103763192184260801 MTIME=??? ?? ??:?? ???? 
> FIX? yes
> 
> BAD FILE SIZE
> UNEXPECTED SOFT UPDATE INCONSISTENCY
> I=6891264  OWNER=1746441326 MODE=146121
> SIZE=10103763192184260801 MTIME=??? ?? ??:?? ???? 
> CLEAR? yes
> 
> INODE CHECK-HASH FAILED I=6891265  OWNER=2967366544 MODE=22404
> SIZE=6465710959960971806 MTIME=??? ?? ??:?? ???? 
> FIX? yes
> 
> BAD FILE SIZE
> UNEXPECTED SOFT UPDATE INCONSISTENCY
> I=6891265  OWNER=2967366544 MODE=22404
> SIZE=6465710959960971806 MTIME=??? ?? ??:?? ???? 
> CLEAR? yes
> 
> INODE CHECK-HASH FAILED I=6891266  OWNER=3055313325 MODE=55724
> SIZE=11494838078614539290 MTIME=??? ?? ??:?? ???? 
> 
> . . .
> 
> (The list of reports is massive and growing. I'll be regenerating
> the media content, starting with a dd.)
> 



===
Mark Millard
marklmi at yahoo.com