On 1/9/25 07:02, Marko Hoyer wrote:
Am 09.01.25 um 00:26 schrieb Rob Landley:
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 ...
Buffering or not in the char device is a driver choice. If your serial
hardware has a small FIFO buffer and the driver doesn't do its own layer
of output buffering (with a tasklet or something to copy the data to the
hardware), then the write() syscall will block waiting for the data to
go out. (Writes to filesystems stopped doing this back around 2.0 or
something, when they rewrote the vfs to be based on the page cache and
deentry cache, meaning ALL filesystem writes go through that now unless
you say O_DIRECT to _ask_ for it to block, which isn't even always
honored. But for some reason the TTY layer drives people insane, and
char devices have been given a wide berth...)
There's a similar issue with some xterms where "make -j16 build"
spamming lots of output to a display terminal can run significantly
slower than "make -j16 build | cat" because the linux pipe
infrastructure inserts a pipe buffer (ulimit -p says 8 but I think
that's _pages_ so 32k? Except in 2.6.11 it was 64k? Eh, not looking it
up...) so the writes from each cc instance go into the pipe buffer and
return immediately when it's not full, whereas writes to a terminal
device block until the terminal has finished updating (which includes
scrolling the screen).
If I recall (many years ago), the kde terminal implementation included a
buffer of its own (immediately returned before updating), and the gnome
one didn't (blocked until x11 display update completed), so foreground
builds were faster under kde.
And the gnome guys' answer was to spray everything down with 3D
acceleration so the GPU was scrolling the screen for you, because of
course it was.
Anyway, serialized latency has _always_ killed throughput, because it's
a cost you can't get BACK. The kernel guys used to know this:
https://yarchive.net/comp/linux/raid0.html
Hence the old high school math problem: if you have 2 hours to go 100
miles and you travel the first 40 miles at 20 miles per hour, how fast
do you have to go the rest to make it on time? Answer: you'd have to
instantaneously teleport because you spent 2 hours going 40 miles and
your time is up with 60 miles left to go. Optimizing the wrong part
DOESN'T HELP.
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.
You can adjust the loglevel so they still go into dmesg but don't go out
to the console, which theoretically shouldn't be THAT slow? (At least
cpu limited rather than wait-for-hardware.)
But keep in mind that a lot of kernel devs seem actively trying to
sabotage embedded development, and the dmesg metadata is now multiple
times the size of the actual payload.
https://lkml.iu.edu/hypermail/linux/kernel/2412.0/00045.html
So trimming the dmesg buffer size is probably ALSO a good idea on modern
embedded systems, because WHAT THE FSCK? Also, I dunno how much cpu time
all that metadata fapping takes. (Before systemd, this was just text
going into a ring buffer. But systemd couldn't cope with that because
https://www.theregister.com/2014/04/05/torvalds_sievers_dust_up/ and
https://en.wikipedia.org/wiki/Systemd#History and of course
https://www.linux.com/news/fun-photo-greg-kroah-hartman-crowned-systemd-hackfest/
thus the data structures in the kernel had to become far more complex
after about 30 years of NOT being like that, because systemd.)
Rob
