Greetings!
While using a usb-serial device as console, I've noticed some
significant gaps in the kernel logs it receives.
The problem can be reproduced in qemu like this (the kernel is a
x86_64_defconfig with usb-serial enabled and with the ftdi_sio driver
enabled):
qemu-system-x86_64 -m 4G -kernel arch/x86_64/boot/bzImage -usb -device
usb-serial,chardev=ser -chardev pty,id=ser -append 'console=ttyUSB0'
(this will create a `pts` device that will connect to the other end of
the emulated usb-serial)
Then the logs look something like this:
[ 1.006459] SELinux: Initializing.
[ 1.011620] Mount-cache hash table entries: 8192 (order: 4, 65536
bytes, li[ 2.315341] ACPI: \_SB_.LNKD: Enabled at IRQ 11
This probably happens because of the code in
`usb_serial_generic_write` which tries to insert the data into the
fifo:
count = kfifo_in_locked(&port->write_fifo, buf, count, &port->lock);
Because added indications for when the result is less than expected
and it showed significant losses.
The return value is silently ignored in `usb_console_write`
Also making the fifo bigger in `setup_port_bulk_out` helped (I made it
10 times bigger and there were no losses)
The reason so much data is written at a short time is because
usb-serial is initialized rather late, and when it is registered as a
console, all the logs until this point are written to it.
I'm not sure what the solution should be. Maybe we need to check
whether the write in `console_emit_next_record` was successful and not
increase the seq counter in this case.
Any suggestions?
On Sun, Oct 29, 2023 at 08:21:21PM +0200, ariel marcovitch wrote:
> Greetings!
>
> While using a usb-serial device as console, I've noticed some
> significant gaps in the kernel logs it receives.
>
> The problem can be reproduced in qemu like this (the kernel is a
> x86_64_defconfig with usb-serial enabled and with the ftdi_sio driver
> enabled):
> qemu-system-x86_64 -m 4G -kernel arch/x86_64/boot/bzImage -usb -device
> usb-serial,chardev=ser -chardev pty,id=ser -append 'console=ttyUSB0'
> (this will create a `pts` device that will connect to the other end of
> the emulated usb-serial)
>
> Then the logs look something like this:
> [ 1.006459] SELinux: Initializing.
> [ 1.011620] Mount-cache hash table entries: 8192 (order: 4, 65536
> bytes, li[ 2.315341] ACPI: \_SB_.LNKD: Enabled at IRQ 11
>
> This probably happens because of the code in
> `usb_serial_generic_write` which tries to insert the data into the
> fifo:
> count = kfifo_in_locked(&port->write_fifo, buf, count, &port->lock);
> Because added indications for when the result is less than expected
> and it showed significant losses.
> The return value is silently ignored in `usb_console_write`
> Also making the fifo bigger in `setup_port_bulk_out` helped (I made it
> 10 times bigger and there were no losses)
>
> The reason so much data is written at a short time is because
> usb-serial is initialized rather late, and when it is registered as a
> console, all the logs until this point are written to it.
>
> I'm not sure what the solution should be. Maybe we need to check
> whether the write in `console_emit_next_record` was successful and not
> increase the seq counter in this case.
>
> Any suggestions?
Please realize that usb-serial console was the result of me loosing a
drunken bet. It's amazing it works at all. For "fake" devices like
this, that use the generic usb-serial code, yes, you will have overruns
and other problems, that's just part of how it works (i.e. not well.)
For something like qemu, please use a real console, like the serial port
(i.e. a fake serial port), not the fake usb-serial port.
So this is "working as designed" in that it wasn't designed at all and
again, it is a miracle any data is flowing there at all :)
sorry,
greg k-h
On Mon, 30 Oct 2023 at 08:22, Greg KH <[email protected]> wrote:
>
> On Sun, Oct 29, 2023 at 08:21:21PM +0200, ariel marcovitch wrote:
> > Greetings!
> >
> > While using a usb-serial device as console, I've noticed some
> > significant gaps in the kernel logs it receives.
> >
> > The problem can be reproduced in qemu like this (the kernel is a
> > x86_64_defconfig with usb-serial enabled and with the ftdi_sio driver
> > enabled):
> > qemu-system-x86_64 -m 4G -kernel arch/x86_64/boot/bzImage -usb -device
> > usb-serial,chardev=ser -chardev pty,id=ser -append 'console=ttyUSB0'
> > (this will create a `pts` device that will connect to the other end of
> > the emulated usb-serial)
> >
> > Then the logs look something like this:
> > [ 1.006459] SELinux: Initializing.
> > [ 1.011620] Mount-cache hash table entries: 8192 (order: 4, 65536
> > bytes, li[ 2.315341] ACPI: \_SB_.LNKD: Enabled at IRQ 11
> >
> > This probably happens because of the code in
> > `usb_serial_generic_write` which tries to insert the data into the
> > fifo:
> > count = kfifo_in_locked(&port->write_fifo, buf, count, &port->lock);
> > Because added indications for when the result is less than expected
> > and it showed significant losses.
> > The return value is silently ignored in `usb_console_write`
> > Also making the fifo bigger in `setup_port_bulk_out` helped (I made it
> > 10 times bigger and there were no losses)
> >
> > The reason so much data is written at a short time is because
> > usb-serial is initialized rather late, and when it is registered as a
> > console, all the logs until this point are written to it.
> >
> > I'm not sure what the solution should be. Maybe we need to check
> > whether the write in `console_emit_next_record` was successful and not
> > increase the seq counter in this case.
> >
> > Any suggestions?
>
> Please realize that usb-serial console was the result of me loosing a
> drunken bet. It's amazing it works at all. For "fake" devices like
LOL your drunken bet was quite helpful to some people
Because modern PCs come without a serial port, I wanted to use it to
see early logs on my crashing kernel without having to use printk
delay and things like that.
I'm curious as to how kernel people debug PCs in general...
In any case, the usb-serial setup was quite weird as it required two
usb-serial and a gender changer
> this, that use the generic usb-serial code, yes, you will have overruns
> and other problems, that's just part of how it works (i.e. not well.)
>
> For something like qemu, please use a real console, like the serial port
> (i.e. a fake serial port), not the fake usb-serial port.
Yeah I was just using it to demonstrate the problem (I agree it is
quite weird to use usb-serial as a console for qemu)
I experienced the same problem with a real usb-serial device, then I
tried to use emulation so I can debug it more easily
>
> So this is "working as designed" in that it wasn't designed at all and
> again, it is a miracle any data is flowing there at all :)
I see...
However it may be possible to fix it without much effort, so why not?
Something like checking the return value for the console's write
function seems reasonable to me anyway...
Besides, don't other types of consoles have the same problem (being
initialized late, getting a lot of data, losing some of it)?
>
> sorry,
>
> greg k-h
Thank you for your honest feedback,
Ariel Marcovitch
On Mon, Oct 30, 2023 at 10:15:30AM +0200, ariel marcovitch wrote:
> > Please realize that usb-serial console was the result of me loosing a
> > drunken bet. It's amazing it works at all. For "fake" devices like
> LOL your drunken bet was quite helpful to some people
> Because modern PCs come without a serial port, I wanted to use it to
> see early logs on my crashing kernel without having to use printk
> delay and things like that.
> I'm curious as to how kernel people debug PCs in general...
We use a usb debug port connection (it's a special cable).
> In any case, the usb-serial setup was quite weird as it required two
> usb-serial and a gender changer
Yes, that's normal.
> > this, that use the generic usb-serial code, yes, you will have overruns
> > and other problems, that's just part of how it works (i.e. not well.)
> >
> > For something like qemu, please use a real console, like the serial port
> > (i.e. a fake serial port), not the fake usb-serial port.
> Yeah I was just using it to demonstrate the problem (I agree it is
> quite weird to use usb-serial as a console for qemu)
> I experienced the same problem with a real usb-serial device, then I
> tried to use emulation so I can debug it more easily
Which real usb-serial device? That matters as it's up to the individual
driver to handle the flow control properly.
> > So this is "working as designed" in that it wasn't designed at all and
> > again, it is a miracle any data is flowing there at all :)
> I see...
> However it may be possible to fix it without much effort, so why not?
> Something like checking the return value for the console's write
> function seems reasonable to me anyway...
But overflows for buffers can not be handled by consoles like this
> Besides, don't other types of consoles have the same problem (being
> initialized late, getting a lot of data, losing some of it)?
Yes, they do have that problem, this is not unique. You can just see it
very easily when using the generic usb-serial driver as there is almost
no buffering at all in it other than what the tty layer provides.
Adding larger buffers can help with this, but where do you stop? What
is the proper buffer size to always use?
Overall, if you are going to be doing lots of debugging of early-boot
and console logs, I recommend getting a usb debug cable instead, sorry.
usb-serial console is just "best effort" and we're happy that any data
flows out of the thing at all :)
thanks,
greg k-h
On Mon, Oct 30, 2023 at 09:30:15AM +0100, Greg KH wrote:
> On Mon, Oct 30, 2023 at 10:15:30AM +0200, ariel marcovitch wrote:
> > > Please realize that usb-serial console was the result of me loosing a
> > > drunken bet. It's amazing it works at all. For "fake" devices like
> > LOL your drunken bet was quite helpful to some people
> > Because modern PCs come without a serial port, I wanted to use it to
> > see early logs on my crashing kernel without having to use printk
> > delay and things like that.
> > I'm curious as to how kernel people debug PCs in general...
>
> We use a usb debug port connection (it's a special cable).
Sometimes people use netconsole (see
Documentation/networking/netconsole.rst). I don't know how common it is
nowadays, and it may not be quite as reliable as a debug port device,
but it should still work. And it doesn't require special hardware.
Alan Stern
On 10/30/23 07:19, Alan Stern wrote:
> On Mon, Oct 30, 2023 at 09:30:15AM +0100, Greg KH wrote:
>> On Mon, Oct 30, 2023 at 10:15:30AM +0200, ariel marcovitch wrote:
>>>> Please realize that usb-serial console was the result of me loosing a
>>>> drunken bet. It's amazing it works at all. For "fake" devices like
>>> LOL your drunken bet was quite helpful to some people
>>> Because modern PCs come without a serial port, I wanted to use it to
>>> see early logs on my crashing kernel without having to use printk
>>> delay and things like that.
>>> I'm curious as to how kernel people debug PCs in general...
>>
>> We use a usb debug port connection (it's a special cable).
For EHCI it is a special cable. For XHCI you can use a special cable but
it is not required. (I saw a few people on LKML say that a normal data cable
works so I tested it and it does work.)
But if you want the special cable (for XHCI), this one works:
https://www.datapro.net/products/usb-3-0-super-speed-a-a-debugging-cable.html
So I tested with both the special debug cable and a normal A-A data cable,
both with satisfactory results.
> Sometimes people use netconsole (see
> Documentation/networking/netconsole.rst). I don't know how common it is
> nowadays, and it may not be quite as reliable as a debug port device,
> but it should still work. And it doesn't require special hardware.
It would be great if netconsole worked with wifi and not wired (ethernet).
--
~Randy