Bug 242732 - Slow boot on Raspberry Pi 2B (armv7) on 12.1-RELEASE
Summary: Slow boot on Raspberry Pi 2B (armv7) on 12.1-RELEASE
Status: Open
Alias: None
Product: Base System
Classification: Unclassified
Component: arm (show other bugs)
Version: 12.1-RELEASE
Hardware: arm Any
: --- Affects Only Me
Assignee: freebsd-arm (Nobody)
URL:
Keywords: needs-qa, performance
Depends on:
Blocks:
 
Reported: 2019-12-19 22:39 UTC by JustIgnoreMe
Modified: 2019-12-26 18:17 UTC (History)
1 user (show)

See Also:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description JustIgnoreMe 2019-12-19 22:39:15 UTC
When booting a Raspberry Pi 2B (armv7) on 12.1R, the boot process is slow (well slower than it should be).

In the output of:
Booting [boot/kernel/kernel] in XX seconds, each second displayed takes approximately 9 seconds in real time to elapse.
Comment 1 Kubilay Kocak freebsd_committer freebsd_triage 2019-12-20 09:17:17 UTC
Is system performance otherwise OK post boot? 

If so, is there a certain point at which this 'performance transition' takes place?

Could you include a verbose boot log as an attachment
Comment 2 JustIgnoreMe 2019-12-20 10:41:59 UTC
Unfortunately, it will not restart.

If there are ANY usb storage devices attached, then right at the beginning it shows:
Starting USB...
Bus usb@7e980000: scanning usb@7e980000 for devices...

And then it just sits there.

So I powered off. Removed the USB stick and kept the USB keyboard in. It now passes this test and moves on.

Unfortunately, it now gets to the:
ue0: <USB ethernet> on smsc0
ue0: Ethernet address:

And there it has remained for the last 20 minutes. It's not working.


Anyway, to your question, the slowness occurs at the uboot message and continues on until the kernel is booting.

This was what I observed on a freshly installed FreeBSD. I only ever booted it that once until now and now it's dead. It will not boot.

I will close this. Thanks for your time.
Comment 3 JustIgnoreMe 2019-12-20 11:17:25 UTC
Just as a final note, I decided to remove the small extension USB cable connecting the USB stick to the PI and plug the USB stick in directly to the Pi.

It now boots ok and there's no delay.
-------------------------------------

The odd thing is I booted Devuan (debian) on the same RPI 2B with the USB drive attached to the extension cable and it had no problem booting.

So there's obviously something very precise about the timings/resistance on the USB bus that causes this issue with FreeBSD but not Linux.
Comment 4 Bob Prohaska 2019-12-20 17:54:53 UTC
Removing an extension cable is one way to raise the voltage a little
at the device.

If you haven't yet checked, take a look at the power supply voltage.
It's on pin 2 (outside corner GPIO header) and 39 (inside, other end
of header). 

I went through a similar goose chase after two years of relatively
good luck with a Pi2. Discovered the power supply was sick. Replaced
it and the machine now seems to work much better.

It might be a red herring, but I was _extremely_ surprised to find the
power supply had gone bad. Adding a powered hub for the USB flash
device seemed to help, and that was my first clue to look for power
troubles.
Comment 5 JustIgnoreMe 2019-12-21 01:26:23 UTC
I never thought of the issue of power, mainly because this works with Linux, no problem. I however just checked the voltage. It's 5.17v.

The oddity is, as explained, it works fine with Linux (Devuan/Debian).

I took your advice, and attached a powered hub to it. It still refused to get past the:

Starting USB...
Bus usb@7e980000: scanning usb@7e980000 for devices...

So, I suspect there is an underlying issue with FreeBSD's implementation of the USB "standards". I can work with the current USB connected directly to the Pi (or I can go back to Linux...)
Comment 6 JustIgnoreMe 2019-12-21 01:29:13 UTC
Also, can I add, this only causes an issue upon booting. If after booting you insert the USB sticks attached to an extension cable, FreeBSD functions fine. I have NOT done any tests on throughput.

Kubilay, if you're still reading this, should I re-open this bug and focus it more to the boot portion of USB scanning?
Comment 7 Bob Prohaska 2019-12-21 02:25:33 UTC
(In reply to JustIgnoreMe from comment #5)

 5.17 volts is good, almost too good 8-)

I've had  similar problems, but knowing the voltage is low on
my machine and being unable to get consistent, reproducible failures,
there wasn't much point in complaining. I think yours is a better
case for suggesting something might be wrong with USB's behavior. 

FWIW, a serial console connection to a second computer will make
it much easier to capture the boot transcript and poke around. 
Last I checked it wasn't possible to use keyboard and display
in single-user mode. 

bob prohaska
Comment 8 JustIgnoreMe 2019-12-21 02:54:36 UTC
Thanks Bob.
Yes, the power supply on the Raspberry Pi 2B is an official power supply so I expect it's good. The voltage from 5v pins is unregulated so that's what it's getting from the supply.

I have had issues with the Raspberry Pi 4 and a Chinese power supply that says one thing on the label and another on a multimeter.

I was hoping to add boot_verbose="YES" to loader.conf and see if that suffices and avoid serial console connection.
Comment 9 Bob Prohaska 2019-12-21 03:55:21 UTC
(In reply to JustIgnoreMe from comment #8)

The trouble is it's very hard to communicate the results of the
verbose boot unless they show up on a machine with a GUI and a net
connection. If they do, it's just a copy and paste job. Otherwise,
it's manual transcription or photographs of the screen.

Also, I don't think it's possible to interact with u-boot and loader
when the machine is in trouble without a serial console. That may 
have changed by now, but not so far as I know. 

HTH,

bob prohaska
Comment 10 Bob Prohaska 2019-12-23 18:31:06 UTC
Fixed the power supply problem, my Pi2 v. 1.1 is now getting 5.09 volts
measured at the GPIO header. Uname reports
FreeBSD 12.1-STABLE #3 r355995M: Sun Dec 22 17:22:41 PST 2019
    bob@www.zefox.com:/usr/obj/usr/src/arm.armv7/sys/GENERIC arm

The M in the revision number is due to adding device pass to the
RPI2 kernel config file, which isn't in use.


The strange part of the boot log contains

umass0 on uhub1
umass0: <SanDisk Extreme, class 0/0, rev 2.10/0.10, addr 4> on usbus0
Root mount waiting for: usbus0 CAM
ugen0.5: <FTDI USB - Serial> at Root mount waiting for: CAM
Root mount waiting for: CAM
Root mount waiting for: CAM

This message repeats about 80 times, followed by

Root mount waiting for: CAM
Root mount waiting for: CAM
(probe0:umass-sim0:0:0:0): INQUIRY. CDB: 12 00 00 00 24 00 
Root mount waiting for:(probe0:umass-sim0:0:0:0): CAM status: CCB request completed with an error
 CAM(probe0:umass-sim0:0:0:0): Retrying command, 3 more tries remain

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 AA010509160727180727
da0: 40.000MB/s transfers
da0: 59836MB (122544516 512 byte sectors)
da0: quirks=0x2<NO_6_BYTE>
Warning: no time-of-day clock registered, system time will not be set accurately

From this point on the boot looks normal as the machine goes multi-user.

Reaction to ssh is slow, it takes about ten seconds to return a password prompt.
This is after nameservice is primed. Otherwise bahavior is unremarkable.

I'd be glad to post the complete, verbatim boot log if it's helpful and
comments can be that long. The whole thing will close to 300 lines.

Thanks for reading!

bob prohaska
Comment 11 Bob Prohaska 2019-12-26 18:17:42 UTC
FWIW, a similar message is now being presented by AARCH64 on a PI3 at
FreeBSD 13.0-CURRENT #0 r356048:

kbd1 at ukbd0
Root mount waiting for: usbus0 CAM
ugen0.7: <vendor 0x413c product 0x3010> at usbus0
ugen0.8: <vendor 0x067b product 0x2303> at usbus0
Root mount waiting for: CAM
Root mount waiting for: CAM
Root mount waiting for: CAM
Root mount waiting for: CAM
Root mount waiting for: CAM
Root mount waiting for: CAM
Root mount waiting for: CAM
Root mount waiting for: CAM
Root mount waiting for: CAM
Root mount waiting for: CAM
Root mount waiting for: CAM
Root mount waiting for: CAM
da0 at umass-sim0 bus 0 scbus0 target 0 lun 0
da0: <SanDisk Extreme 0001> Removable Direct Access SPC-4 SCSI device

The wait in this case is much shorter, being shown in its entirety.

Both the Pi2 and Pi3 have in /boot/loader.conf the lines

kern.cam.boot_delay="20000"
 and
vfs.root_mount_always_wait="1"

Ssh login on the Pi3 takes less than a second, the Pi2 requires around five
to put up a password prompt and another five to display a shell prompt.

The machine continues to hang with 
Timeout poll on interrupt endpoint 
when keyboard and mouse are connected, but can be unstuck by typing
boot
on the serial console.

Thanks for reading!

bob prohaska