imx serial chars lost issue

imx serial chars lost issue

[Francesco Dolcini]

Hello all,
recently I have been experiencing an issue with the imx uart on i.MX6ULL
SoC, on the tty console (no flow control, 1152008n1), chars after the 32nd
are lost when typing "fast" (copy/paste or writing to the uart using
automated tools).

This was tested on Linux 6.0, however it does not look like a brand new
regression, kernel 5.4 was somehow subject to the same issue, although
it was way more difficult to trigger it.

While I do understand that without flow control this is something that
cannot be prevented, it is pretty fishy that is always the chars after
the 32nd.

I guess that might be happening is that the FIFO is emptied only by a
timer or when it is full, instead of emptying it when half-full, and the
CPU might not be fast enough leading to an overflow and the chars lost.

Any idea?

Francesco

Re: imx serial chars lost issue

[Fabio Estevam]

Hi Francesco,

On Mon, Oct 3, 2022 at 8:08 AM Francesco Dolcini
<francesco.dolcini@toradex.com> wrote:
>
> Hello all,
> recently I have been experiencing an issue with the imx uart on i.MX6ULL

Does this also happen with other i.MX devices or only on i.MX6ULL?

> SoC, on the tty console (no flow control, 1152008n1), chars after the 32nd
> are lost when typing "fast" (copy/paste or writing to the uart using
> automated tools).
>
> This was tested on Linux 6.0, however it does not look like a brand new
> regression, kernel 5.4 was somehow subject to the same issue, although
> it was way more difficult to trigger it.
>
> While I do understand that without flow control this is something that
> cannot be prevented, it is pretty fishy that is always the chars after
> the 32nd.
>
> I guess that might be happening is that the FIFO is emptied only by a
> timer or when it is full, instead of emptying it when half-full, and the
> CPU might not be fast enough leading to an overflow and the chars lost.
>
> Any idea?

Can you share a reproducer?

Re: imx serial chars lost issue

[Uwe Kleine-König]

[-- Attachment #1: Type: text/plain, Size: 2178 bytes --]

Hello Francesco,

On Mon, Oct 03, 2022 at 01:08:50PM +0200, Francesco Dolcini wrote:
> recently I have been experiencing an issue with the imx uart on i.MX6ULL
> SoC, on the tty console (no flow control, 1152008n1), chars after the 32nd
> are lost when typing "fast" (copy/paste or writing to the uart using
> automated tools).
> 
> This was tested on Linux 6.0, however it does not look like a brand new
> regression, kernel 5.4 was somehow subject to the same issue, although
> it was way more difficult to trigger it.
> 
> While I do understand that without flow control this is something that
> cannot be prevented, it is pretty fishy that is always the chars after
> the 32nd.
> 
> I guess that might be happening is that the FIFO is emptied only by a
> timer or when it is full, instead of emptying it when half-full, and the
> CPU might not be fast enough leading to an overflow and the chars lost.
> 
> Any idea?

It's not unheared that there are bugs in the imx serial driver, but I'm
at least half confident that it's not a driver issue.

I guess commit 7a637784d517 ("serial: imx: reduce RX interrupt
frequency") is relevant, this was added in v5.18-rc1.

If this is really the commit that made the issue easier to reproduce,
then this is a hint that there is no functional problem and we're "just"
talking about irq latency issues. If enabling flow control solves the
issue, this is another hint in the same direction.

So I think this is what happens:

The other side starts sending chars at a high frequency. Once the RX
FIFO fill level reaches 8 an irq is triggered. Now if there are 25 more
characters received before the irq is serviced you get an overflow and
loose chars. Without 7a637784d517 there is a bit more time (i.e. 7
character times).

So either you use a very high baud rate that is hard to handle (compared
to the cpu frequency), or this is a side effect of increased irq
latency (which is likely a problem somewhere else).

Best regards
Uwe

-- 
Pengutronix e.K.                           | Uwe Kleine-König            |
Industrial Linux Solutions                 | https://www.pengutronix.de/ |

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 488 bytes --]

Re: imx serial chars lost issue

[Francesco Dolcini]

On Wed, Oct 26, 2022 at 12:06:34AM -0300, Fabio Estevam wrote:
> Hi Francesco,
> 
> On Mon, Oct 3, 2022 at 8:08 AM Francesco Dolcini
> <francesco.dolcini@toradex.com> wrote:
> >
> > Hello all,
> > recently I have been experiencing an issue with the imx uart on i.MX6ULL
> 
> Does this also happen with other i.MX devices or only on i.MX6ULL?

I do not know for sure, I did not try to actively reproduce the issue on
another SoC. On the other hand the issue with the i.MX6ULL was noticed
during some testing, and we do exactly the same tests on other SoC and
there the issue is either not present or just happening very
infrequently.

> > SoC, on the tty console (no flow control, 1152008n1), chars after the 32nd
> > are lost when typing "fast" (copy/paste or writing to the uart using
> > automated tools).
> >
> > This was tested on Linux 6.0, however it does not look like a brand new
> > regression, kernel 5.4 was somehow subject to the same issue, although
> > it was way more difficult to trigger it.
> >
> > While I do understand that without flow control this is something that
> > cannot be prevented, it is pretty fishy that is always the chars after
> > the 32nd.
> >
> > I guess that might be happening is that the FIFO is emptied only by a
> > timer or when it is full, instead of emptying it when half-full, and the
> > CPU might not be fast enough leading to an overflow and the chars lost.
> >
> > Any idea?
> 
> Can you share a reproducer?

Just open the uart console with a terminal application and copy/paste the
following:

 echo -n "12345678901234567890123456789012345678901234567890123456789012345678901234567890" | wc

This is supposed to count 80 chars, you'll get less.

For doing that minicom is not a good choice since we noticed that it
introduces quite some delay between each chars, while using `screen` I
am able to reproduce the issue systematically. We initially reproduced
the issue using `ser2net` with the exact same test.

Francesco

Re: imx serial chars lost issue

[Francesco Dolcini]

On Wed, Oct 26, 2022 at 08:56:04AM +0200, Uwe Kleine-König wrote:
> On Mon, Oct 03, 2022 at 01:08:50PM +0200, Francesco Dolcini wrote:
> > recently I have been experiencing an issue with the imx uart on i.MX6ULL
> > SoC, on the tty console (no flow control, 1152008n1), chars after the 32nd
> > are lost when typing "fast" (copy/paste or writing to the uart using
> > automated tools).
> > 
> > This was tested on Linux 6.0, however it does not look like a brand new
> > regression, kernel 5.4 was somehow subject to the same issue, although
> > it was way more difficult to trigger it.
> > 
> > While I do understand that without flow control this is something that
> > cannot be prevented, it is pretty fishy that is always the chars after
> > the 32nd.
> > 
> > I guess that might be happening is that the FIFO is emptied only by a
> > timer or when it is full, instead of emptying it when half-full, and the
> > CPU might not be fast enough leading to an overflow and the chars lost.
> > 
> > Any idea?
> 
> It's not unheared that there are bugs in the imx serial driver, but I'm
> at least half confident that it's not a driver issue.
> 
> I guess commit 7a637784d517 ("serial: imx: reduce RX interrupt
> frequency") is relevant, this was added in v5.18-rc1.
> 
> If this is really the commit that made the issue easier to reproduce,
> then this is a hint that there is no functional problem and we're "just"
> talking about irq latency issues. If enabling flow control solves the
> issue, this is another hint in the same direction.

I can confirm that reverting 7a637784d517 makes the issue more difficult to
reproduce, and even when it is reproduced the amount of chars lost is
decreased. Enabling HW flow control is not trivial to test.

> The other side starts sending chars at a high frequency. Once the RX
> FIFO fill level reaches 8 an irq is triggered. Now if there are 25 more
> characters received before the irq is serviced you get an overflow and
> loose chars. Without 7a637784d517 there is a bit more time (i.e. 7
> character times).
> 
> So either you use a very high baud rate that is hard to handle (compared
> to the cpu frequency), or this is a side effect of increased irq
> latency (which is likely a problem somewhere else).

The uart is configured as 115200 8n1, 86usec per char, given the 25
chars FIFO is 2.150msec to service the irq and get the data out of the
fifo.

Just thinking at the MHz the CPU is 792MHz, however it can (and will)
scale down to 198MHz.

I would say that something like that should be reasonable to handle, but
it's just my gut feeling ...

Francesco

Re: imx serial chars lost issue

[Lucas Stach]

Hi Francesco,

Am Mittwoch, dem 26.10.2022 um 09:32 +0200 schrieb Francesco Dolcini:
> On Wed, Oct 26, 2022 at 12:06:34AM -0300, Fabio Estevam wrote:
> > Hi Francesco,
> > 
> > On Mon, Oct 3, 2022 at 8:08 AM Francesco Dolcini
> > <francesco.dolcini@toradex.com> wrote:
> > > 
> > > Hello all,
> > > recently I have been experiencing an issue with the imx uart on i.MX6ULL
> > 
> > Does this also happen with other i.MX devices or only on i.MX6ULL?
> 
> I do not know for sure, I did not try to actively reproduce the issue on
> another SoC. On the other hand the issue with the i.MX6ULL was noticed
> during some testing, and we do exactly the same tests on other SoC and
> there the issue is either not present or just happening very
> infrequently.
> 
IRQ latency is influenced by lots of things like CPU frequency and idle
behavior and the involved drivers on a specific SoC, as they might
disable interrupt processing for too long.

To test the hypothesis you can enable CONFIG_IRQSOFF_TRACER and then
see if you find any smoking gun by running your testcase with this
tracer enabled.

Regards,
Lucas

> > > SoC, on the tty console (no flow control, 1152008n1), chars after the 32nd
> > > are lost when typing "fast" (copy/paste or writing to the uart using
> > > automated tools).
> > > 
> > > This was tested on Linux 6.0, however it does not look like a brand new
> > > regression, kernel 5.4 was somehow subject to the same issue, although
> > > it was way more difficult to trigger it.
> > > 
> > > While I do understand that without flow control this is something that
> > > cannot be prevented, it is pretty fishy that is always the chars after
> > > the 32nd.
> > > 
> > > I guess that might be happening is that the FIFO is emptied only by a
> > > timer or when it is full, instead of emptying it when half-full, and the
> > > CPU might not be fast enough leading to an overflow and the chars lost.
> > > 
> > > Any idea?
> > 
> > Can you share a reproducer?
> 
> Just open the uart console with a terminal application and copy/paste the
> following:
> 
>  echo -n "12345678901234567890123456789012345678901234567890123456789012345678901234567890" | wc
> 
> This is supposed to count 80 chars, you'll get less.
> 
> For doing that minicom is not a good choice since we noticed that it
> introduces quite some delay between each chars, while using `screen` I
> am able to reproduce the issue systematically. We initially reproduced
> the issue using `ser2net` with the exact same test.
> 
> Francesco
> 
> 

Re: imx serial chars lost issue

[Sergey Organov]

Francesco Dolcini <francesco@dolcini.it> writes:

> On Wed, Oct 26, 2022 at 12:06:34AM -0300, Fabio Estevam wrote:
>> Hi Francesco,
>> 
>> On Mon, Oct 3, 2022 at 8:08 AM Francesco Dolcini
>> <francesco.dolcini@toradex.com> wrote:
>> >
>> > Hello all,
>> > recently I have been experiencing an issue with the imx uart on i.MX6ULL
>> 
>> Does this also happen with other i.MX devices or only on i.MX6ULL?
>
> I do not know for sure, I did not try to actively reproduce the issue on
> another SoC. On the other hand the issue with the i.MX6ULL was noticed
> during some testing, and we do exactly the same tests on other SoC and
> there the issue is either not present or just happening very
> infrequently.
>
>> > SoC, on the tty console (no flow control, 1152008n1), chars after the 32nd
>> > are lost when typing "fast" (copy/paste or writing to the uart using
>> > automated tools).
>> >
>> > This was tested on Linux 6.0, however it does not look like a brand new
>> > regression, kernel 5.4 was somehow subject to the same issue, although
>> > it was way more difficult to trigger it.
>> >
>> > While I do understand that without flow control this is something that
>> > cannot be prevented, it is pretty fishy that is always the chars after
>> > the 32nd.
>> >
>> > I guess that might be happening is that the FIFO is emptied only by a
>> > timer or when it is full, instead of emptying it when half-full, and the
>> > CPU might not be fast enough leading to an overflow and the chars lost.
>> >
>> > Any idea?
>> 
>> Can you share a reproducer?
>
> Just open the uart console with a terminal application and copy/paste the
> following:
>
>  echo -n "12345678901234567890123456789012345678901234567890123456789012345678901234567890" | wc
>
> This is supposed to count 80 chars, you'll get less.

I've tested this on my board featuring iMX6SX CPU, using socat on both
ends of the serial line:

On PC, using MOXA multi-port serial board:

$ echo -n "12345678901234567890123456789012345678901234567890123456789012345678901234567890" |  socat - /dev/ttyMI3,cfmakeraw,b115200

while running

$ socat -u /dev/ttymxc5,cfmakeraw,b115200 ./log

on the board, and I got exactly 80 bytes in the ./log.

The kernel running does not contain mentioned 7a637784d517 ("serial:
imx: reduce RX interrupt frequency") though, so maybe it's just that.

-- Sergey Organov

Re: imx serial chars lost issue

[Sergey Organov]

Francesco Dolcini <francesco@dolcini.it> writes:

> On Wed, Oct 26, 2022 at 08:56:04AM +0200, Uwe Kleine-König wrote:
>> On Mon, Oct 03, 2022 at 01:08:50PM +0200, Francesco Dolcini wrote:
>> > recently I have been experiencing an issue with the imx uart on i.MX6ULL
>> > SoC, on the tty console (no flow control, 1152008n1), chars after the 32nd
>> > are lost when typing "fast" (copy/paste or writing to the uart using
>> > automated tools).
>> > 
>> > This was tested on Linux 6.0, however it does not look like a brand new
>> > regression, kernel 5.4 was somehow subject to the same issue, although
>> > it was way more difficult to trigger it.
>> > 
>> > While I do understand that without flow control this is something that
>> > cannot be prevented, it is pretty fishy that is always the chars after
>> > the 32nd.
>> > 
>> > I guess that might be happening is that the FIFO is emptied only by a
>> > timer or when it is full, instead of emptying it when half-full, and the
>> > CPU might not be fast enough leading to an overflow and the chars lost.
>> > 
>> > Any idea?
>> 
>> It's not unheared that there are bugs in the imx serial driver, but I'm
>> at least half confident that it's not a driver issue.
>> 
>> I guess commit 7a637784d517 ("serial: imx: reduce RX interrupt
>> frequency") is relevant, this was added in v5.18-rc1.
>> 
>> If this is really the commit that made the issue easier to reproduce,
>> then this is a hint that there is no functional problem and we're "just"
>> talking about irq latency issues. If enabling flow control solves the
>> issue, this is another hint in the same direction.
>
> I can confirm that reverting 7a637784d517 makes the issue more difficult to
> reproduce, and even when it is reproduced the amount of chars lost is
> decreased. Enabling HW flow control is not trivial to test.
>
>> The other side starts sending chars at a high frequency. Once the RX
>> FIFO fill level reaches 8 an irq is triggered. Now if there are 25 more
>> characters received before the irq is serviced you get an overflow and
>> loose chars. Without 7a637784d517 there is a bit more time (i.e. 7
>> character times).
>> 
>> So either you use a very high baud rate that is hard to handle (compared
>> to the cpu frequency), or this is a side effect of increased irq
>> latency (which is likely a problem somewhere else).
>
> The uart is configured as 115200 8n1, 86usec per char, given the 25
> chars FIFO is 2.150msec to service the irq and get the data out of the
> fifo.
>
> Just thinking at the MHz the CPU is 792MHz, however it can (and will)
> scale down to 198MHz.
>
> I would say that something like that should be reasonable to handle, but
> it's just my gut feeling ...

A wild guess: make sure you don't use Linux kernel console on serial
port, i.e., /proc/consoles is empty. Serial console may disable
interrupts for very long time intervals due to kernel printk()
implementation.

I've got random data loss on serial ports when turning on and off WiFi
on my board (that caused some printk() diagnostic from the kernel) due
to this deficiency. Took ages to isolate.

-- Sergey Organov