Gaps in logs while using usb-serial as a console

Gaps in logs while using usb-serial as a console

[ariel marcovitch]

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?

Re: Gaps in logs while using usb-serial as a console

[Greg KH]

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

Re: Gaps in logs while using usb-serial as a console

[ariel marcovitch]

On Mon, 30 Oct 2023 at 08:22, Greg KH <gregkh@linuxfoundation.org> 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

Re: Gaps in logs while using usb-serial as a console

[Greg KH]

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

Re: Gaps in logs while using usb-serial as a console

[Alan Stern]

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

Re: Gaps in logs while using usb-serial as a console

[Randy Dunlap]

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

Re: Gaps in logs while using usb-serial as a console

[ariel marcovitch]

Hello and sorry for the delay

On Mon, 30 Oct 2023 at 10:30, Greg KH <gregkh@linuxfoundation.org> 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).
Interesting
What makes it work well as opposed to usb-serial? Is it a less
complicated format?
What code is responsible for this feature?
>
> > 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.
Oh sorry I really thought I mentioned but it seems I missed it: pl2302
Isn't the problem generic, though? (The speed of the device may make some
difference probably)
>
> > > 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?
Specifically, since we are talking about data coming from the console,
and it saves the full log anyway (or at least buffers a lot of it, in
a configurable manner),
why can't it make the per-console seq track the actual data that was
able to be sent?
It sound reasonable for me, is it really that bad?
>
> 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
Thanks,
Ariel Marcovitch

Re: Gaps in logs while using usb-serial as a console

[Greg KH]

On Thu, Nov 09, 2023 at 08:55:49PM +0200, ariel marcovitch wrote:
> Hello and sorry for the delay
> 
> On Mon, 30 Oct 2023 at 10:30, Greg KH <gregkh@linuxfoundation.org> 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).
> Interesting
> What makes it work well as opposed to usb-serial? Is it a less
> complicated format?

Yes, it looks like a serial console you just write the characters to and
they come out the other end.  No messing around with USB stuff.

> What code is responsible for this feature?

drivers/usb/host/xhci-dbgtty.c

> > > 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.
> Oh sorry I really thought I mentioned but it seems I missed it: pl2302
> Isn't the problem generic, though? (The speed of the device may make some
> difference probably)

The type of device and the speed it is sending out the characters makes
all the difference here.  A pl2303 device is a very tiny and dumb uart
with almost no buffer in it at all.  Overruns will happen if you try to
use a console to get boot messages.

> > > > 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?
> Specifically, since we are talking about data coming from the console,
> and it saves the full log anyway (or at least buffers a lot of it, in
> a configurable manner),
> why can't it make the per-console seq track the actual data that was
> able to be sent?
> It sound reasonable for me, is it really that bad?

Try changing it and see!  :)

It's complex stuff, there is buffering already, but for slow devices
with no additional buffers in them, you will have overruns.

But hey, I could be totally wrong here, patches are always gladly
reviewed for this stuff if you find some places that could be improved.

thanks,

greg k-h