g_vfs_done():ufs/rootfs[WRITE flood on rpi3

From: bob prohaska <fbsd_at_www.zefox.net>
Date: Wed, 20 Nov 2019 14:37:03 -0800
While compiling a kernel at r354909 using a system at
r354845 the serial console flooded with messages of the
form 
g_vfs_done():ufs/rootfs[WRITE(offset=266534912, length=32768)]error = 5

occasionally interspersed with

mmcsd0: Error indicated: 1 Timeout
g_vfs_done():ufs/rootfs[WRITE(offset=268697600, length=32768)]emmcsd0: Error indicated: 1 Timeout

It looked like the microSD card had finally failed, but breaking to
the debugger and rebooting seems to have recovered normally: The kernel
build picked up where it left off and the new kernel appears to boot
and run. 

The console output follows, the "Timeout poll on interrupt endpoint"
messages are an artifact of an old Dell keyboard. :


g_vfs_done():ufs/rootfs[WRITE(offset=10178002944, length=32768)]error = 5
g_vfs_done():ufs/rootfs[WRITE(offset=185663488, length=131072)]error = 5
g_vfs_done():ufs/rootfs[WRITE(offset=185794560, length=65536)]error = 5
g_vfs_done():ufs/rootfs[WRITE(offset=185958400, length=131072)]error = 5
g_vfs_done():ufs/rootfs[WRITE(offset=186089472, length=65536)]error = 5
g_vfs_done():ufs/rootfs[WRITE(offset=186286080, length=32768)]error = 5
g_vfs_done():ufs/rootfs[WRITE(offset=186384384, length=98304)]error = 5
g_vfs_done():ufs/rootfs[WRITE(offset=186515456, length=65536)]error = 5
g_vfs_done():ufs/rootfs[WRITE(offset=186908672, length=32768)]error = 5
KDB: enter: Break to debugger
g_vfs_done():ufs/rootfs[WRITE(offset=188809216, length=65536)]e[ thread pid 12 tid 100015 ]
Stopped at      0
db> bt
Tracing pid 12 tid 100015 td 0xfffffd00009b9000
db_trace_self() at db_stack_trace+0xf8
         pc = 0xffff00000072953c  lr = 0xffff00000010398c
         sp = 0xffff00004f14dce0  fp = 0xffff00004f14dd10

db_stack_trace() at db_command+0x228
         pc = 0xffff00000010398c  lr = 0xffff000000103604
         sp = 0xffff00004f14dd20  fp = 0xffff00004f14de00

db_command() at db_command_loop+0x58
         pc = 0xffff000000103604  lr = 0xffff0000001033ac
         sp = 0xffff00004f14de10  fp = 0xffff00004f14de30

db_command_loop() at db_trap+0xf4
         pc = 0xffff0000001033ac  lr = 0xffff0000001066b0
         sp = 0xffff00004f14de40  fp = 0xffff00004f14e060

db_trap() at kdb_trap+0x1d8
         pc = 0xffff0000001066b0  lr = 0xffff0000004491dc
         sp = 0xffff00004f14e070  fp = 0xffff00004f14e120
        
kdb_trap() at do_el1h_sync+0xf4
         pc = 0xffff0000004491dc  lr = 0xffff000000746400
         sp = 0xffff00004f14e130  fp = 0xffff00004f14e160

do_el1h_sync() at handle_el1h_sync+0x78
         pc = 0xffff000000746400  lr = 0xffff00000072b878
         sp = 0xffff00004f14e170  fp = 0xffff00004f14e280

handle_el1h_sync() at kdb_alt_break_internal+0x130
         pc = 0xffff00000072b878  lr = 0xffff000000448994
         sp = 0xffff00004f14e290  fp = 0xffff00004f14e330

kdb_alt_break_internal() at kdb_alt_break+0xc
         pc = 0xffff000000448994  lr = 0xffff000000448854
         sp = 0xffff00004f14e340  fp = 0xffff00004f14e340

kdb_alt_break() at uart_intr_rxready+0x88
         pc = 0xffff000000448854  lr = 0xffff0000002623f0
         sp = 0xffff00004f14e350  fp = 0xffff00004f14e370
        
uart_intr_rxready() at uart_intr+0xec
         pc = 0xffff0000002623f0  lr = 0xffff0000002630d8
         sp = 0xffff00004f14e380  fp = 0xffff00004f14e3b0

uart_intr() at intr_event_handle+0xc8
         pc = 0xffff0000002630d8  lr = 0xffff0000003c3df0
         sp = 0xffff00004f14e3c0  fp = 0xffff00004f14e400

intr_event_handle() at intr_isrc_dispatch+0x34
         pc = 0xffff0000003c3df0  lr = 0xffff00000077c624
         sp = 0xffff00004f14e410  fp = 0xffff00004f14e420

intr_isrc_dispatch() at bcm2835_intc_intr+0xa8
         pc = 0xffff00000077c624  lr = 0xffff000000718658
         sp = 0xffff00004f14e430  fp = 0xffff00004f14e470

bcm2835_intc_intr() at intr_event_handle+0xc8
         pc = 0xffff000000718658  lr = 0xffff0000003c3df0
         sp = 0xffff00004f14e480  fp = 0xffff00004f14e4c0
        
intr_event_handle() at intr_isrc_dispatch+0x34
         pc = 0xffff0000003c3df0  lr = 0xffff00000077c624
         sp = 0xffff00004f14e4d0  fp = 0xffff00004f14e4e0

intr_isrc_dispatch() at bcm_lintc_intr+0x1e8
         pc = 0xffff00000077c624  lr = 0xffff00000071e5ac
         sp = 0xffff00004f14e4f0  fp = 0xffff00004f14e570

bcm_lintc_intr() at intr_irq_handler+0x74
         pc = 0xffff00000071e5ac  lr = 0xffff00000077c484
         sp = 0xffff00004f14e580  fp = 0xffff00004f14e5a0

intr_irq_handler() at handle_el1h_irq+0x74
         pc = 0xffff00000077c484  lr = 0xffff00000072b938
         sp = 0xffff00004f14e5b0  fp = 0xffff00004f14e6c0

handle_el1h_irq() at vt_flush+0x3a0
         pc = 0xffff00000072b938  lr = 0xffff0000002cb310
         sp = 0xffff00004f14e6d0  fp = 0xffff00004f14e760
        
vt_flush() at vt_flush+0x3a0
         pc = 0xffff0000002cb310  lr = 0xffff0000002cb310
         sp = 0xffff00004f14e770  fp = 0xffff00004f14e7b0

vt_flush() at vt_timer+0x10
         pc = 0xffff0000002cb310  lr = 0xffff0000002ca788
         sp = 0xffff00004f14e7c0  fp = 0xffff00004f14e7d0

vt_timer() at softclock_call_cc+0x11c
         pc = 0xffff0000002ca788  lr = 0xffff00000041a5b0
         sp = 0xffff00004f14e7e0  fp = 0xffff00004f14e880

softclock_call_cc() at softclock+0x84
         pc = 0xffff00000041a5b0  lr = 0xffff00000041a994
         sp = 0xffff00004f14e890  fp = 0xffff00004f14e8b0

softclock() at ithread_loop+0x1e8
         pc = 0xffff00000041a994  lr = 0xffff0000003c44d4
         sp = 0xffff00004f14e8c0  fp = 0xffff00004f14e940
        
ithread_loop() at fork_exit+0x7c
         pc = 0xffff0000003c44d4  lr = 0xffff0000003c0f98
         sp = 0xffff00004f14e950  fp = 0xffff00004f14e980

fork_exit() at fork_trampoline+0x10
         pc = 0xffff0000003c0f98  lr = 0xffff00000074618c
         sp = 0xffff00004f14e990  fp = 0x0000000000000000

db> reboot
MMC:   mmc_at_7e300000: 1
Loading Environment from FAT... *** Warning - bad CRC, using default environment

In:    serial
Out:   vidconsole
Err:   vidconsole
Net:   No ethernet found.
starting USB...
USB0:   scanning bus 0 for devices... unable to get device descriptor (error=-22)
7 USB Device(s) found
       scanning usb for storage devices... 1 Storage Device(s) found
Hit any key to stop autoboot:  2 Timeout poll on interrupt endpoint
Timeout poll on interrupt endpoint
 1 Timeout poll on interrupt endpoint
 0 
Timeout poll on interrupt endpoint
MMC Device 0 not found
no mmc device at slot 0
Timeout poll on interrupt endpoint
switch to partitions #0, OK
mmc1 is current device
Timeout poll on interrupt endpoint
Scanning mmc 1:1...
Timeout poll on interrupt endpoint
Timeout poll on interrupt endpoint
Timeout poll on interrupt endpoint
Timeout poll on interrupt endpoint
Timeout poll on interrupt endpoint
Timeout poll on interrupt endpoint
Timeout poll on interrupt endpoint
Timeout poll on interrupt endpoint
Timeout poll on interrupt endpoint
Timeout poll on interrupt endpoint
Timeout poll on interrupt endpoint
Timeout poll on interrupt endpoint
Timeout poll on interrupt endpoint
Found EFI removable media binary efi/boot/bootaa64.efi
libfdt fdt_check_header(): FDT_ERR_BADMAGIC
Timeout poll on interrupt endpoint
                                                                                          Timeout poll on interrupt endpoint
Scanning disk mmc_at_7e300000.blk...
Scanning disk usb_mass_storage.lun0...
Found 13 disks
FDT memrsv map 0: Failed to add to map
BootOrder not defined
637000 bytes read in 44 ms (13.8 MiB/s)
libfdt fdt_check_header(): FDT_ERR_BADMAGIC
FDT memrsv map 0: Failed to add to map
## Starting EFI application at 00080000 ...
Consoles: EFI console  
FreeBSD/arm64 EFI loader, Revision 1.1

   Command line arguments: loader.efi
   EFI version: 2.70
   EFI Firmware: Das U-Boot (rev 8217.1024)
   Console: efi (0)
   Load Path: /VenHw(e61d73b9-a384-4acc-aeab-82e828f3628b)/SD(1)/SD(0)/HD(1,0x01,0,0x81f,0x18fa8)/efi\boot\bootaa64.efi
   Load Device: /VenHw(e61d73b9-a384-4acc-aeab-82e828f3628b)/SD(1)/SD(0)/HD(1,0x01,0,0x81f,0x18fa8)
Trying ESP: /VenHw(e61d73b9-a384-4acc-aeab-82e828f3628b)/SD(1)/SD(0)/HD(1,0x01,0,0x81f,0x18fa8)
Setting currdev to disk0p1:
Trying: /VenHw(e61d73b9-a384-4acc-aeab-82e828f3628b)/SD(1)/SD(0)/HD(2,0x01,0,0x197c7,0xee66839)
Setting currdev to disk0p2:
Loading /boot/defaults/loader.conf
Loading /boot/device.hints
Loading /boot/loader.conf
Loading /boot/loader.conf.local
Loading kernel...
/boot/kernel/kernel text=0x96e9c4 data=0x189b30 data=0x0+0x79aee0 syms=[0x8+0x141f30+0x8+0x12cd90]
Loading configured modules...
/boot/kernel/umodem.ko text=0x2100 text=0x13a0 data=0x6e0+0x10 syms=[0x8+0xf48+0x8+0xb6e]
/boot/entropy size=0x1000

Hit [Enter] to boot immediately, or any other key for command prompt.


Type '?' for a list of commands, 'help' for more detailed help.
OK Timeout poll on interrupt endpoint
Timeout poll on interrupt endpoint
Timeout poll on interrupt endpoint
Timeout poll on interrupt endpoint
Timeout poll on interrupt endpoint
boTimeout poll on interrupt endpoint
ot
Using DTB provided by EFI at 0x7ef6000.
Timeout poll on interrupt endpoint
Timeout poll on interrupt endpoint
Timeout poll on interrupt endpoint
Timeout poll on interrupt endpoint
Timeout poll on interrupt endpoint
Timeout poll on interrupt endpoint
Timeout poll on interrupt endpoint
Timeout poll on interrupt endpoint
Timeout poll on interrupt endpoint
Timeout poll on interrupt endpoint
Timeout poll on interrupt endpoint
Timeout poll on interrupt endpoint
Timeout poll on interrupt endpoint
EFI framebuffer information:
addr, size     0x3e330000, 0x8ca000
dimensions     1920 x 1200
stride         1920
masks          0x00ff0000, 0x0000ff00, 0x000000ff, 0xff000000
---<<BOOT>>---
KDB: debugger backends: ddb
KDB: current backend: ddb
Copyright (c) 1992-2019 The FreeBSD Project.
Copyright (c) 1979, 1980, 1983, 1986, 1988, 1989, 1991, 1992, 1993, 1994
	The Regents of the University of California. All rights reserved.
FreeBSD is a registered trademark of The FreeBSD Foundation.
FreeBSD 13.0-CURRENT #2 r354845: Wed Nov 20 07:55:37 PST 2019
    bob_at_www.zefox.org:/usr/obj/usr/src/arm64.aarch64/sys/GENERIC arm64
FreeBSD clang version 9.0.0 (tags/RELEASE_900/final 372316) (based on LLVM 9.0.0)
WARNING: WITNESS option enabled, expect reduced performance.
VT(efifb): resolution 1920x1200
module firmware already present!
KLD file umodem.ko is missing dependencies
Starting CPU 1 (1)
Starting CPU 2 (2)
Starting CPU 3 (3)
FreeBSD/SMP: Multiprocessor System Detected: 4 CPUs
random: unblocking device.
random: entropy device external interface
MAP 7ef6000 mode 2 pages 20
MAP 39f43000 mode 2 pages 1
MAP 39f52000 mode 2 pages 1
MAP 3b350000 mode 2 pages 16
MAP 3f100000 mode 0 pages 1
kbd0 at kbdmux0
ofwbus0: <Open Firmware Device Tree>
simplebus0: <Flattened device tree simple bus> on ofwbus0
ofw_clkbus0: <OFW clocks bus> on ofwbus0
clk_fixed0: <Fixed clock> on ofw_clkbus0
clk_fixed1: <Fixed clock> on ofw_clkbus0
regfix0: <Fixed Regulator> on ofwbus0
regfix1: <Fixed Regulator> on ofwbus0
psci0: <ARM Power State Co-ordination Interface Driver> on ofwbus0
lintc0: <BCM2836 Interrupt Controller> mem 0x40000000-0x400000ff on simplebus0
intc0: <BCM2835 Interrupt Controller> mem 0x7e00b200-0x7e00b3ff irq 20 on simplebus0
gpio0: <BCM2708/2835 GPIO controller> mem 0x7e200000-0x7e2000b3 irq 22,23 on simplebus0
gpiobus0: <OFW GPIO bus> on gpio0
generic_timer0: <ARMv7 Generic Timer> irq 0,1,2,3 on ofwbus0
Timecounter "ARM MPCore Timecounter" frequency 19200000 Hz quality 1000
Event timer "ARM MPCore Eventtimer" frequency 19200000 Hz quality 1000
usb_nop_xceiv0: <USB NOP PHY> on ofwbus0
bcm_dma0: <BCM2835 DMA Controller> mem 0x7e007000-0x7e007eff irq 4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19 on simplebus0
bcmwd0: <BCM2708/2835 Watchdog> mem 0x7e100000-0x7e100027 on simplebus0
bcm2835_clkman0: <BCM283x Clock Manager> mem 0x7e101000-0x7e102fff on simplebus0
bcmrng0: <Broadcom BCM2835 RNG> mem 0x7e104000-0x7e10400f on simplebus0
mbox0: <BCM2835 VideoCore Mailbox> mem 0x7e00b880-0x7e00b8bf irq 21 on simplebus0
gpioc0: <GPIO controller> on gpio0
uart0: <PrimeCell UART (PL011)> mem 0x7e201000-0x7e201fff irq 24 on simplebus0
uart0: console (115200,n,8,1)
spi0: <BCM2708/2835 SPI controller> mem 0x7e204000-0x7e204fff irq 26 on simplebus0
spibus0: <OFW SPI bus> on spi0
spibus0: <unknown card> at cs 0 mode 0
spibus0: <unknown card> at cs 1 mode 0
iichb0: <BCM2708/2835 BSC controller> mem 0x7e804000-0x7e804fff irq 37 on simplebus0
bcm283x_dwcotg0: <DWC OTG 2.0 integrated USB controller (bcm283x)> mem 0x7e980000-0x7e98ffff,0x7e006000-0x7e006fff irq 43,44 on simplebus0
usbus0 on bcm283x_dwcotg0
sdhci_bcm0: <Broadcom 2708 SDHCI controller> mem 0x7e300000-0x7e3000ff irq 46 on simplebus0
mmc0: <MMC/SD bus> on sdhci_bcm0
fb0: <BCM2835 VT framebuffer driver> on simplebus0
fb0: keeping existing fb bpp of 32
fbd0 on fb0
VT: Replacing driver "efifb" with new "fb".
fb0: 1920x1200(1920x1200_at_0,0) 32bpp
fb0: fbswap: 1, pitch 7680, base 0x3e330000, screen_size 9216000
pmu0: <Performance Monitoring Unit> irq 50 on simplebus0
cpulist0: <Open Firmware CPU Group> on ofwbus0
cpu0: <Open Firmware CPU> on cpulist0
bcm2835_cpufreq0: <CPU Frequency Control> on cpu0
cpu1: <Open Firmware CPU> on cpulist0
cpu2: <Open Firmware CPU> on cpulist0
cpu3: <Open Firmware CPU> on cpulist0
gpioled0: <GPIO LEDs> on ofwbus0
gpioled0: <led0> failed to map pin
gpioled0: <led1> failed to map pin
cryptosoft0: <software crypto>
Timecounters tick every 1.000 msec
usbus0: 480Mbps High Speed USB v2.0
iicbus0: <OFW I2C bus> on iichb0
iic0: <I2C generic I/O> on iicbus0
ugen0.1: <DWCOTG OTG Root HUB> at usbus0
uhub0 on usbus0
uhub0: <DWCOTG OTG Root HUB, class 9/0, rev 2.00/1.00, addr 1> on usbus0
mmcsd0: 128GB <SDHC ED4QT 3.0 SN 9B9A5304 MFG 05/2018 by 27 SM> at mmc0 50.0MHz/4bit/65535-block
bcm2835_cpufreq0: ARM 600MHz, Core 250MHz, SDRAM 400MHz, Turbo OFF
mbox0: mbox response error
bcm2835_cpufreq0: can't set clock rate (id=4)
mbox0: mbox response error
bcm2835_cpufreq0: can't set clock rate (id=8)
uhub0: 1 port with 1 removable, self powered
ugen0.2: <vendor 0x0424 product 0x9514> at usbus0
uhub1 on uhub0
uhub1: <vendor 0x0424 product 0x9514, class 9/0, rev 2.00/2.00, addr 2> on usbus0
uhub1: MTT enabled
uhub1: 5 ports with 4 removable, self powered
ugen0.3: <vendor 0x0424 product 0xec00> at usbus0
smsc0 on uhub1
smsc0: <vendor 0x0424 product 0xec00, rev 2.00/2.00, addr 3> on usbus0
smsc0: chip 0xec00, rev. 0002
miibus0: <MII bus> on smsc0
smscphy0: <SMC LAN8700 10/100 interface> PHY 1 on miibus0
smscphy0:  10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, auto
ue0: <USB Ethernet> on smsc0
ue0: Ethernet address: b8:27:eb:ba:68:d5
ugen0.4: <SanDisk Extreme> at usbus0
umass0 on uhub1
umass0: <SanDisk Extreme, class 0/0, rev 2.10/0.10, addr 4> on usbus0
umass0:  SCSI over Bulk-Only; quirks = 0x0100
umass0:0:0: Attached to scbus0
ugen0.5: <Dell Dell USB Keyboard Hub> at usbus0
uhub2 on uhub1
uhub2: <Dell USB Keyboard Hub> on usbus0
uhub2: 3 ports with 2 removable, bus powered
ugen0.6: <Dell Dell USB Keyboard Hub> at usbus0
ukbd0 on uhub2
ukbd0: <Dell USB Keyboard Hub> on usbus0
kbd1 at ukbd0
ugen0.7: <vendor 0x413c product 0x3010> at usbus0
ugen0.8: <vendor 0x067b product 0x2303> at usbus0
Release APs...done
da0 at umass-sim0 bus 0 scbus0 target 0 lun 0
da0: <SanDisk Extreme 0001> Removable Direct Access SPC-4 SCSI device
da0: Serial Number AA010428162242131598
da0: 40.000MB/s transfers
da0: 59836MB (122544516 512 byte sectors)
da0: quirks=0x2<NO_6_BYTE>
CPU  0: ARM Cortex-A53 r0p4 affinity:  0
 Instruction Set Attributes 0 = <CRC32>
Trying to mount root from ufs:/dev/ufs/rootfs [rw]...
 Instruction Set Attributes 1 = <>
         Processor Features 0 = <AdvSIMD,FP,EL3 32,EL2 32,EL1 32,EL0 32>
         Processor Features 1 = <>
      Memory Model Features 0 = <TGran4,TGran64,SNSMem,BigEnd,16bit ASID,1TB PA>
      Memory Model Features 1 = <8bit VMID>
      Memory Model Features 2 = <32bit CCIDX,48bit VA>
             Debug Features 0 = <2 CTX BKPTs,4 Watchpoints,6 Breakpoints,PMUv3,Debugv8>
             Debug Features 1 = <>
         Auxiliary Features 0 = <>
         Auxiliary Features 1 = <>
CPU  1: ARM Cortex-A53 r0p4 affinity:  1
CPU  2: ARM Cortex-A53 r0p4 affinity:  2
CPU  3: ARM Cortex-A53 r0p4 affinity:  3
WARNING: WITNESS option enabled, expect reduced performance.
WARNING: / was not properly dismounted
WARNING: /: mount pending error: blocks 48 files 6
Warning: no time-of-day clock registered, system time will not be set accurately
Setting hostuuid: 30303030-3030-3030-3064-626136386435.
Setting hostid: 0x5cd40a6a.
warning: total configured swap (1101063 pages) exceeds maximum recommended amount (920808 pages).
warning: increase kern.maxswzone or reduce amount of swap.
warning: total configured swap (2411783 pages) exceeds maximum recommended amount (920808 pages).
warning: increase kern.maxswzone or reduce amount of swap.
Starting file system checks:

At this point things returned to normal.

Thanks for reading, I hope it's useful.

bob prohaska
Received on Wed Nov 20 2019 - 21:37:04 UTC

This archive was generated by hypermail 2.4.0 : Wed May 19 2021 - 11:41:22 UTC