Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 23.128.96.32 as permitted sender) client-ip=23.128.96.32;
MIME-Version: 1.0
References: <CAFGKuwoFUaXMsOOWJNBenQDG6+syt80Z9pvQQK1XSZFztC2_SQ@mail.gmail.com>
 <2023103052-unpeeled-calibrate-ae48@gregkh>
In-Reply-To: <2023103052-unpeeled-calibrate-ae48@gregkh>
From:   ariel marcovitch <arielmarcovitch@gmail.com>
Date:   Mon, 30 Oct 2023 10:15:30 +0200
Message-ID: <CAFGKuwp7JH8H9vjz8iJ24R9TRW0GDE-O96VBAG4L8X4DhTabXg@mail.gmail.com>
Subject: Re: Gaps in logs while using usb-serial as a console
To:     Greg KH <gregkh@linuxfoundation.org>
Cc:     johan@kernel.org, linux-usb@vger.kernel.org,
        Linux Kernel Mailing List <linux-kernel@vger.kernel.org>
Content-Type: text/plain; charset="UTF-8"
Precedence: bulk

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