Am 09.01.25 um 00:26 schrieb Rob Landley:
On 1/8/25 15:19, Bird, Tim wrote:
Cases:
- #1 quiet: cmdline w/ quiet, no kernel or userspace output up to the
serial login console
- #2 normal: cmdline w/o quiet, serial console @115200 baud
- #3 normal_baud9600: cmdline w/o quiet, serial console @9600 baud
Main outcomes:
- kernel timestamps "Run /sbin/init as init process"
#1: "1.714458", #2: "3.011701", #3: "16.108101"
Wow from 1.7 seconds to 16.1 seconds. That's a pretty huge
difference. I guess this particular technique is still
very relevant!
CONFIG_EARLY_PRINTK output is emitted before interrupts are enabled
(last I checked they didn't kick in until RIGHT before PID 1 gets
forked off), so the early output drivers spin waiting for the next
character to go into the buffer (the memory mapped register ones look
something like "while (MASK&*status); *output = *data++;" in a for
loop) and the printk() call can't return until all the data has been
queued to the serial hardware, so you spend a lot of time blocked in
printk().
Hi Rob,
thx for the explanation, helps further!
* This implementation would explain the observed behavior.
* What I'm not understanding yet: logs from systemd delay systemd the
same way as seen in the kernel. Looks like the issue is not solved even
when PID 1 is started. As said, It can be something specific to single
core SoCs or even just to RPI Zero W. I'll check ...
With 9600 baud 8n1 output, 9600/9 = 1066 characters per second, or
approximately a 1ms wait between each character, blocking in printk
when the hardware FIFO buffer fills up, so 16k of output data takes 16
seconds to write if the rest of the boot is doing NOTHING. Even a 1k
hardware FIFO is only 1 second of output, and that's assuming all 1k
is outgoing rather than split between in/out.
Your options are:
1) disable early printk so it all goes into a malloced buffer until
interrupts are enabled and it can be asynchronously flushed (meaning
if something DOES go wrong in early boot you can't see it)
2) set your FIFO speed as fast as possible
3) have your default boot use the "quiet" option (similar to disabling
EARLY_PRINTK but at least you have the option to yank quiet from your
bootloader args without rebuilding the kernel.)
Faster UART speeds mean shorter serial cables (although there's also 3
volt vs 5 volt, wire thickness/capacitance, and some other stuff, Jeff
Dionne walked me through the math last year but I don't have my notes
in front of me). Modern hardware can do up to 4 megabits/second but
outside "this serial chip immediately talks to a USB chip and then
it's transported as USB with the funky noise-cancelling signaling over
VERY twisted pair to actually leave the board"), I wouldn't trust that
over any real length of cable.
Alas
https://tldp.org/HOWTO/Remote-Serial-Console-HOWTO/serial-distance.html
is from the dawn of time and only goes up to 56k over wires made from
recycled drainpipes.
https://novatel.com/support/known-solutions/maximum-cable-length-vs-data-rate
says 115200 is 2.5 meters. It LOOKS like it scales linearly with twice
the speed being half the cable, so a megabit would be about 1 foot of
serial cable before the bits get all mushy.
As said in another mail: I do not know a valid (production) use case in
which kernel logs need to be dumped to a serial console. I regard this
mechanism only as useful for development purposes (in which fast boot is
probably not so relevant). Please correct me if I'm wrong, would be
happy to learn about such use cases.
Based on that I think option 3) is the best options for most cases.
Rob
Marko
