Date: Wed, 28 Aug 2013 12:30:00 GMT From: Ian Lepore <ian@FreeBSD.org> To: freebsd-arm@FreeBSD.org Subject: Re: arm/181601: Sporadic failure of root mount on ARM/Raspberry Message-ID: <201308281230.r7SCU0k5093956@freefall.freebsd.org>
next in thread | raw e-mail | index | archive | help
The following reply was made to PR arm/181601; it has been noted by GNATS. From: Ian Lepore <ian@FreeBSD.org> To: Martin Laabs <info@martinlaabs.de> Cc: freebsd-gnats-submit@FreeBSD.org Subject: Re: arm/181601: Sporadic failure of root mount on ARM/Raspberry Date: Wed, 28 Aug 2013 06:23:02 -0600 On Wed, 2013-08-28 at 05:35 +0000, Martin Laabs wrote: > >Number: 181601 > >Category: arm > >Synopsis: Sporadic failure of root mount on ARM/Raspberry > >Confidential: no > >Severity: non-critical > >Priority: low > >Responsible: freebsd-arm > >State: open > >Quarter: > >Keywords: > >Date-Required: > >Class: sw-bug > >Submitter-Id: current-users > >Arrival-Date: Wed Aug 28 05:40:00 UTC 2013 > >Closed-Date: > >Last-Modified: > >Originator: Martin Laabs > >Release: FreeBSD 10.0-CURRENT #0 r254955M > >Organization: > - > >Environment: > not available > >Description: > Sporadicly the raspberry pi failes to mount its root mmc card. After power off and power on again works most of the time. However there seem to be also configurations that fail permanently. Unfortunately I have no image of a sd card that fails on every boot. The full boot log output is attached to this bug report. > > > Trying to mount root from ufs:/dev/mmcsd0s2a [rw,noatime]... > mountroot: waiting for device /dev/mmcsd0s2a ... > smsc0: chip 0xec00, rev. 0002 > miibus0: <MII bus> on smsc0 > ukphy0: <Generic IEEE 802.3u media interface> PHY 1 on miibus0 > ukphy0: none, 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, auto > ue0: <USB Ethernet> on smsc0 > ue0: Ethernet address: b8:27:eb:1d:b7:5a > Mounting from ufs:/dev/mmcsd0s2a failed with error 19. > > Loader variables: > vfs.root.mountfrom=ufs:/dev/mmcsd0s2a > vfs.root.mountfrom.options=rw,noatime > > Manual root filesystem specification: > <fstype>:<device> [options] > Mount <device> using filesystem <fstype> > and with the specified (optional) option list. > > eg. ufs:/dev/da0s1a > zfs:tank > cd9660:/dev/acd0 ro > (which is equivalent to: mount -t cd9660 -o ro /dev/acd0 /) > > ? List valid disk boot devices > . Yield 1 second (for background tasks) > <empty line> Abort manual input > > mountroot> > > >How-To-Repeat: > Boot the Raspberry Pi several times and look if > >Fix: > > > Patch attached with submission follows: > > > > U-Boot 2013.01-rc1-g6709570-dirty (Aug 17 2013 - 23:35:05) > > DRAM: 480 MiB > WARNING: Caches not enabled > MMC: bcm2835_sdhci: 0 > Using default environment > > In: serial > Out: lcd > Err: lcd > mbox: Timeout waiting for response > bcm2835: Could not set USB power state > Net: Net Initialization Skipped > No ethernet found. > Hit any key to stop autoboot: 3 2 1 0 > reading uEnv.txt > 89 bytes read in 9541 ms (0 Bytes/s) > Importing environment from mmc ... > reading ubldr > 239540 bytes read in 54396 ms (3.9 KiB/s) > ## Starting application at 0x02000054 ... > Consoles: U-Boot console > Compatible API signature found @1db682a8 > Number of U-Boot devices: 1 > > FreeBSD/armv6 U-Boot loader, Revision 1.2 > (martin@pcbsd-7130, Wed Aug 28 01:32:51 CEST 2013) > DRAM: 480MB > > Device: disk > |/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|Loading /boot/defaults/loader.conf > /-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\/boot/kernel/kernel data=0x47b5e4+0x17e19c |/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|syms=[0x4+0x7fcb0/-\|/-\|/-\|/-\|+0x4+0x4d 613/-\|/-\|/-] > > Hit [Enter] to boot immediately, or any other key for command prompt. > Booting [/boot/kernel/kernel]... > \|/-\|/Using DTB provided by U-Boot. > Kernel entry at 0x100100... > Kernel args: (null) > KDB: debugger backends: ddb > KDB: current backend: ddb > Copyright (c) 1992-2013 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 10.0-CURRENT #0 r254955M: Wed Aug 28 01:32:36 CEST 2013 > martin@pcbsd-7130:/usr/home/martin/Rasperry/crochet-freebsd/work/obj/arm.armv6/usr/home/martin/Rasperry/head/sys/RPI-B arm > FreeBSD clang version 3.3 (tags/RELEASE_33/final 183502) 20130610 > WARNING: WITNESS option enabled, expect reduced performance. > WARNING: DIAGNOSTIC option enabled, expect reduced performance. > CPU: ARM1176JZ-S rev 7 (ARM11J core) > Supported features: ARM_ISA THUMB2 JAZELLE ARMv4 Security_Ext > WB enabled LABT branch prediction enabled > 16KB/32B 4-way instruction cache > 16KB/32B 4-way write-back-locking-C data cache > real memory = 536870912 (512 MB) > avail memory = 482902016 (460 MB) > random device not loaded; using insecure entropy > random: <Software, Yarrow> initialized > simplebus0: <Flattened device tree simple bus> mem 0x20000000-0x20ffffff on fdtbus0 > intc0: <BCM2835 Interrupt Controller> mem 0x2000b200-0x2000b3ff on simplebus0 > systimer0: <BCM2835 System Timer> mem 0x20003000-0x20003fff irq 8,9,10,11 on simplebus0 > Event timer "BCM2835 Event Timer 3" frequency 1000000 Hz quality 1000 > Timecounter "BCM2835 Timecounter" frequency 1000000 Hz quality 1000 > bcmwd0: <BCM2708/2835 Watchdog> mem 0x2010001c-0x20100027 on simplebus0 > gpio0: <BCM2708/2835 GPIO controller> mem 0x20200000-0x202000af irq 57,59,58,60 on simplebus0 > gpio0: read-only pins: 46,47,48,49,50,51,52,53. > gpio0: reserved pins: 48,49,50,51,52,53. > gpioc0: <GPIO controller> on gpio0 > gpiobus0: <GPIO bus> on gpio0 > bcm_dma0: <BCM2835 DMA Controller> mem 0x20007000-0x20007fff,0x20e05000-0x20e05fff irq 24,25,26,27,28,29,30,31,32,33,34,35,36 on simplebus0 > mbox0: <BCM2835 VideoCore Mailbox> mem 0x2000b880-0x2000b8bf irq 1 on simplebus0 > sdhci_bcm0: <Broadcom 2708 SDHCI controller> mem 0x20300000-0x203000ff irq 70 on simplebus0 > mmc0: <MMC/SD bus> on sdhci_bcm0 > uart0: <PrimeCell UART (PL011)> mem 0x20201000-0x20201fff irq 65 on simplebus0 > uart0: console (115200,n,8,1) > dwcotg0: <DWC OTG 2.0 integrated USB controller> mem 0x20980000-0x2099ffff irq 17 on simplebus0 > usbus0 on dwcotg0 > simplebus1: <Flattened device tree simple bus> on fdtbus0 > Timecounters tick every 10.000 msec > lock order reversal: > 1st 0xc06f3c0c entropy harvest mutex (entropy harvest mutex) @ /usr/home/martin/Rasperry/head/sys/dev/random/randomdev_soft.c:242 > 2nd 0xc25d7c20 uart_hwmtx (uart_hwmtx) @ /usr/home/martin/Rasperry/head/sys/dev/uart/uart_cpu.h:92 > KDB: stack backtrace: > db_trace_self() at db_trace_self > pc = 0xc04652cc lr = 0xc012e474 (db_trace_self_wrapper+0x30) > sp = 0xdc20c9c8 fp = 0xdc20cae0 > r10 = 0xc06f3c0c > db_trace_self_wrapper() at db_trace_self_wrapper+0x30 > pc = 0xc012e474 lr = 0xc0268974 (kdb_backtrace+0x38) > sp = 0xdc20cae8 fp = 0xdc20caf0 > r4 = 0xc05908a4 r5 = 0xc049fb59 > r6 = 0xc04bd04d r7 = 0xc049f1d4 > kdb_backtrace() at kdb_backtrace+0x38 > pc = 0xc0268974 lr = 0xc0282df8 (witness_checkorder+0xddc) > sp = 0xdc20caf8 fp = 0xdc20cb48 > r4 = 0xc049fa8a > witness_checkorder() at witness_checkorder+0xddc > pc = 0xc0282df8 lr = 0xc022050c (__mtx_lock_spin_flags+0xc4) > sp = 0xdc20cb50 fp = 0xdc20cb70 > r4 = 0x00000000 r5 = 0xc0580a84 > r6 = 0xc25d7c20 r7 = 0xc25d7c30 > r8 = 0x00000000 r9 = 0x0000005c > r10 = 0xc049fb56 > __mtx_lock_spin_flags() at __mtx_lock_spin_flags+0xc4 > pc = 0xc022050c lr = 0xc014e9a4 (uart_cnputc+0x44) > sp = 0xdc20cb78 fp = 0xdc20cb88 > r4 = 0x0000006c r5 = 0xc0580a84 > r6 = 0xc05908a0 r7 = 0xc0581700 > r8 = 0xc055d590 r9 = 0xc05816e0 > r10 = 0xdc20ccf0 > uart_cnputc() at uart_cnputc+0x44 > pc = 0xc014e9a4 lr = 0xc01eb6b0 (cnputc+0x80) > sp = 0xdc20cb90 fp = 0xdc20cba8 > r4 = 0x0000006c r5 = 0xc0551c30 > r6 = 0xc05908a0 > cnputc() at cnputc+0x80 > pc = 0xc01eb6b0 lr = 0xc026e6ec (putchar+0x194) > sp = 0xdc20cbb0 fp = 0xdc20cc18 > r4 = 0x00000005 r5 = 0xdc20ccf0 > r6 = 0x0000006c r7 = 0x00000000 > r8 = 0xc06f52b4 r9 = 0xc026e558 > putchar() at putchar+0x194 > pc = 0xc026e6ec lr = 0xc026d53c (kvprintf+0xb0) > sp = 0xdc20cc20 fp = 0xdc20ccd8 > r4 = 0xc04bc4c4 r5 = 0x00000000 > r6 = 0x00000000 r7 = 0x00000000 > r8 = 0xc06f52b4 r9 = 0xc026e558 > r10 = 0xdc20ccf0 > kvprintf() at kvprintf+0xb0 > pc = 0xc026d53c lr = 0xc026ec58 (printf+0x50) > sp = 0xdc20cce0 fp = 0xdc20cd10 > r4 = 0xc2446da8 r5 = 0xc2446a68 > r6 = 0x00000000 r7 = 0xc06c394c > r8 = 0xc06f52b4 r9 = 0x00000001 > r10 = 0xc06c395b > printf() at printf+0x50 > pc = 0xc026ec58 lr = 0xc0282b58 (witness_checkorder+0xb3c) > sp = 0xdc20cd28 fp = 0xdc20cd78 > witness_checkorder() at witness_checkorder+0xb3c > pc = 0xc0282b58 lr = 0xc022050c (__mtx_lock_spin_flags+0xc4) > sp = 0xdc20cd80 fp = 0xdc20cda0 > r4 = 0x00000000 r5 = 0x00000000 > r6 = 0xc059198c r7 = 0xc059199c > r8 = 0x00000000 r9 = 0x000000f0 > r10 = 0xc04ba67a > __mtx_lock_spin_flags() at __mtx_lock_spin_flags+0xc4 > pc = 0xc022050c lr = 0xc02751a4 (sleepq_lock+0x34) > sp = 0xdc20cda8 fp = 0xdc20cda8 > r4 = 0xc2582960 r5 = 0x00000000 > r6 = 0xc0580394 r7 = 0x00000000 > r8 = 0xc2584c80 r9 = 0x00000000 > r10 = 0xc0580390 > sleepq_lock() at sleepq_lock+0x34 > pc = 0xc02751a4 lr = 0xc023c4c0 (msleep_spin_sbt+0x80) > sp = 0xdc20cdb0 fp = 0xdc20cdf0 > msleep_spin_sbt() at msleep_spin_sbt+0x80 > pc = 0xc023c4c0 lr = 0xc0147458 (random_kthread+0x270) > sp = 0xdc20cdf8 fp = 0xdc20ce38 > r4 = 0xc06f3c1c r5 = 0x00000000 > r6 = 0xc049f1d1 r7 = 0x00000000 > r8 = 0x00000000 r9 = 0x00000000 > r10 = 0xc0580390 > random_kthread() at random_kthread+0x270 > pc = 0xc0147458 lr = 0xc02033f0 (fork_exit+0x88) > sp = 0xdc20ce40 fp = 0xdc20ce58 > r4 = 0xc2584c80 r5 = 0xc2582960 > r6 = 0xc01471e8 r7 = 0x00000000 > r8 = 0xdc20ce60 r9 = 0x00000000 > r10 = 0x00000000 > fork_exit() at fork_exit+0x88 > pc = 0xc02033f0 lr = 0xc0475cec (fork_trampoline+0x14) > sp = 0xdc20ce60 fp = 0x00000000 > r4 = 0xc01471e8 r5 = 0x00000000 > r6 = 0xc0c0c0c0 r7 = 0xc0c0c0c0 > r8 = 0x00000000 > fork_trampoline() at fork_trampoline+0x14 > pc = 0xc0475cec lr = 0xc0475cec (fork_trampoline+0x14) > sp = 0xdc20ce60 fp = 0x00000000 > Unable to unwind further > lock order reversal: > 1st 0xc06f3c0c entropy harvest mutex (entropy harvest mutex) @ /usr/home/martin/Rasperry/head/sys/dev/random/randomdev_soft.c:242 > 2nd 0xc059198c sleepq chain (sleepq chain) @ /usr/home/martin/Rasperry/head/sys/kern/subr_sleepqueue.c:240 > KDB: stack backtrace: > db_trace_self() at db_trace_self > pc = 0xc04652cc lr = 0xc012e474 (db_trace_self_wrapper+0x30) > sp = 0xdc20cbf8 fp = 0xdc20cd10 > r10 = 0xc06f3c0c > db_trace_self_wrapper() at db_trace_self_wrapper+0x30 > pc = 0xc012e474 lr = 0xc0268974 (kdb_backtrace+0x38) > sp = 0xdc20cd18 fp = 0xdc20cd20 > r4 = 0xc05908a4 r5 = 0xc04ba67d > r6 = 0xc04bd04d r7 = 0xc049f1d4 > kdb_backtrace() at kdb_backtrace+0x38 > pc = 0xc0268974 lr = 0xc0282df8 (witness_checkorder+0xddc) > sp = 0xdc20cd28 fp = 0xdc20cd78 > r4 = 0xc04ba662 > witness_checkorder() at witness_checkorder+0xddc > pc = 0xc0282df8 lr = 0xc022050c (__mtx_lock_spin_flags+0xc4) > sp = 0xdc20cd80 fp = 0xdc20cda0 > r4 = 0x00000000 r5 = 0x00000000 > r6 = 0xc059198c r7 = 0xc059199c > r8 = 0x00000000 r9 = 0x000000f0 > r10 = 0xc04ba67a > __mtx_lock_spin_flags() at __mtx_lock_spin_flags+0xc4 > pc = 0xc022050c lr = 0xc02751a4 (sleepq_lock+0x34) > sp = 0xdc20cda8 fp = 0xdc20cda8 > r4 = 0xc2582960 r5 = 0x00000000 > r6 = 0xc0580394 r7 = 0x00000000 > r8 = 0xc2584c80 r9 = 0x00000000 > r10 = 0xc0580390 > sleepq_lock() at sleepq_lock+0x34 > pc = 0xc02751a4 lr = 0xc023c4c0 (msleep_spin_sbt+0x80) > sp = 0xdc20cdb0 fp = 0xdc20cdf0 > msleep_spin_sbt() at msleep_spin_sbt+0x80 > pc = 0xc023c4c0 lr = 0xc0147458 (random_kthread+0x270) > sp = 0xdc20cdf8 fp = 0xdc20ce38 > r4 = 0xc06f3c1c r5 = 0x00000000 > r6 = 0xc049f1d1 r7 = 0x00000000 > r8 = 0x00000000 r9 = 0x00000000 > r10 = 0xc0580390 > random_kthread() at random_kthread+0x270 > pc = 0xc0147458 lr = 0xc02033f0 (fork_exit+0x88) > sp = 0xdc20ce40 fp = 0xdc20ce58 > r4 = 0xc2584c80 r5 = 0xc2582960 > r6 = 0xc01471e8 r7 = 0x00000000 > r8 = 0xdc20ce60 r9 = 0x00000000 > r10 = 0x00000000 > fork_exit() at fork_exit+0x88 > pc = 0xc02033f0 lr = 0xc0475cec (fork_trampoline+0x14) > sp = 0xdc20ce60 fp = 0x00000000 > r4 = 0xc01471e8 r5 = 0x00000000 > r6 = 0xc0c0c0c0 r7 = 0xc0c0c0c0 > r8 = 0x00000000 > fork_trampoline() at fork_trampoline+0x14 > pc = 0xc0475cec lr = 0xc0475cec (fork_trampoline+0x14) > sp = 0xdc20ce60 fp = 0x00000000 > Unable to unwind further > usbus0: 480Mbps High Speed USB v2.0 > ugen0.1: <DWCOTG> at usbus0 > uhub0: <DWCOTG OTG Root HUB, class 9/0, rev 2.00/1.00, addr 1> on usbus0 > uhub0: 1 port with 1 removable, self powered > mmcsd0: 8GB <SDHC NCard 1.0 SN 1075839384 MFG 05/2013 by 130 JT> at mmc0 50.0MHz/4bit/65535-block > WARNING: WITNESS option enabled, expect reduced performance. > WARNING: DIAGNOSTIC option enabled, expect reduced performance. > mmcsd0: Error indicated: 1 Timeout > mmcsd0: Error indicated: 1 Timeout > Root mount waiting for: usbus0 > ugen0.2: <vendor 0x0424> at usbus0 > uhub1: <vendor 0x0424 product 0x9512, class 9/0, rev 2.00/2.00, addr 2> on usbus0 > uhub1: MTT enabled > Root mount waiting for: usbus0 > uhub1: 3 ports with 2 removable, self powered > Root mount waiting for: usbus0 > ugen0.3: <vendor 0x0424> at usbus0 > smsc0: <vendor 0x0424 product 0xec00, rev 2.00/2.00, addr 3> on usbus0 > Trying to mount root from ufs:/dev/mmcsd0s2a [rw,noatime]... > mountroot: waiting for device /dev/mmcsd0s2a ... > smsc0: chip 0xec00, rev. 0002 > miibus0: <MII bus> on smsc0 > ukphy0: <Generic IEEE 802.3u media interface> PHY 1 on miibus0 > ukphy0: none, 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, auto > ue0: <USB Ethernet> on smsc0 > ue0: Ethernet address: b8:27:eb:1d:b7:5a > Mounting from ufs:/dev/mmcsd0s2a failed with error 19. > > Loader variables: > vfs.root.mountfrom=ufs:/dev/mmcsd0s2a > vfs.root.mountfrom.options=rw,noatime > > Manual root filesystem specification: > <fstype>:<device> [options] > Mount <device> using filesystem <fstype> > and with the specified (optional) option list. > > eg. ufs:/dev/da0s1a > zfs:tank > cd9660:/dev/acd0 ro > (which is equivalent to: mount -t cd9660 -o ro /dev/acd0 /) > > ? List valid disk boot devices > . Yield 1 second (for background tasks) > <empty line> Abort manual input > > mountroot> > > >Release-Note: > >Audit-Trail: > >Unformatted: A little background that may or may not be helpful in investigating this problem... We have long had a problem with mysterious sdcard timeout errors on RPi that doesn't happen on other hardware with sdhci controllers. Until now, it was thought that these timeouts always occurred shortly after the controller was initialized by the OS. The timeouts would affect the early card-detection sequences; we worked around them by adding automatic retries to the mmc code that identifies and initializes cards. This error appears to be a timeout that occurs after the card init sequences are done (the errors are reported by mmcsd0, not mmc0).
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?201308281230.r7SCU0k5093956>