Re: [RFC PATCH v1 00/25] printk: new implementation

[Eugeniu Rosca <erosca@de.adit-jv.com>]

Hi John,

Thank you for the comprehensive feedback. Some replies below.

On Wed, Jan 22, 2020 at 12:56:48AM +0100, John Ogness wrote:
> On 2020-01-21, Eugeniu Rosca <erosca@de.adit-jv.com> wrote:
> > This [1] is a fairly old thread, but I only recently stumbled upon it,
> > while co-investigating below audio distortions [2] on R-Car3 ARM64
> > boards, which can be reproduced by stressing [3] the serial console.
> >
> > The investigation started a few months ago, when users reported audio
> > drops during the first seconds of system startup. Only after a few
> > weeks it became clear (thanks to some people in Cc) that the
> > distortions were contributed by the above-average serial console load
> > during the early boot. Once understood, we were able to come up with a
> > synthetic test [2-3].
> >
> > I thought it would be interesting to share below reproduction matrix,
> > in order to contrast vanilla to linux-rt-devel [4], as well as to
> > compare various preemption models.
> >  
> >                            | Ser.console  Ser.console
> >                            | stressed     at rest or disabled
> >       --------------------------------------------
> >       v5.5-rc6 (PREEMPT=y) | distorted    clean
> >     v5.4.5-rt3 (PREEMPT=y) | distorted    clean
> >  v5.4.5-rt3 (PREEMPT_RT=y) | clean        clean
> >
> > My feeling is that the results probably do not surprise linux-rt
> > people.
> >
> > My first question is, should there be any improvement in the case of
> > v5.4.5-rt3 (PREEMPT=y), which I do not sense? I would expect so, based
> > on the cover letter of this series (pointing out the advantages of the
> > redesigned printk mechanism).
> 
> The problem you are reporting is not the problem that the printk rework
> is trying to solve.

In general, agreed. But there are some quirks and peculiarities in how
the issue (increased audio latency) manifests itself on R-Car3, which
might create some room for a (relatively simple) loophole solution in
the printk mechanism.

With that said, I need to diverge a bit from the platform-agnostic
scope of this series.

So, what's specific to R-Car3, based on my testing, is that the issue
can only be reproduced if the printk storm originates on CPU0 (it does
not matter if from interrupt or task context, both have been tested). If
the printk storm is initiated on any other CPU (there are 7 secondary
ones on R-Car H3), there is no regression in the audio quality/latency.

I cannot fully explain this empirical observation, but it directs my
mind to the following workaround, for which I have a PoC:
 - employ vprintk_safe() any time CPU0 is the owner/caller of printk
 - tie CPU0-private printk internal IRQ workers to another CPU

The above makes sure nothing is printed to the serial console on behalf
of CPU0. I don't even hope this to be accepted by community, but can you
please share your opinion the idea itself is sane?

> 
> In your chart, v5.4.5-rt3 (PREEMPT_RT=y) is the only configuration that
> is _not_ disabling hardware interrupts during UART activity. I would
> guess your problem is due to interrupts being disabled for unacceptable
> lengths of time.

This confirms the internally established view on the issue.

> You need a low-latency system, so PREEMPT_RT=y _is_ the
> correct (and only) solution if a verbose serial console is a must.

It's helpful to have your feedback on this.

> 
> The printk rework focusses on making printk non-interfering by
> decoupling console printing from printk() callers. However, the console
> printing itself will still do just as much interrupt disabling as
> before. That is driver-related, not printk-related.

I didn't dive into the internals of this series, but decoupling the
execution context of the serial driver from the execution context of
the printk callers sounds very good to me (this is what i try to achieve
via vanilla vprintk_safe). I wonder if it's easier to remove CPU0 from
equation with this series applied.

> 
> > And the other question is, how would you, generally speaking, tackle
> > the problem, given that backporting the linux-rt patches is *not* an
> > option and enabling serial console is a must?
> 
> The linux-rt patches (which include this printk rework) *are* being
> ported to mainline now. My recommendation is to continue using the
> linux-rt patches (with PREEMPT_RT=y) until PREEMPT_RT is available
> mainline.

That's an extremely useful feedback. However, I still see non-trivial
differences between mainline and linux-rt-devel:

$ git diff --shortstat v5.4.13..v5.4.13-rt7
  401 files changed, 9577 insertions(+), 3616 deletions(-)

I would be happy to see this slimming down over time. If there is any
roadmap publicly available, I would appreciate a reference.

> 
> John Ogness

Thanks again!

> 
> > [1] https://lore.kernel.org/lkml/20190212143003.48446-1-john.ogness@linutronix.de/
> > [2] H3ULCB> speaker-test -f24_LE -c2 -t wav -Dplughw:rcarsound -b 4000
> >     https://vocaroo.com/9NV98mMgdjX
> > [3] https://github.com/erosca/linux/tree/stress-serial
> > [4] https://git.kernel.org/pub/scm/linux/kernel/git/rt/linux-rt-devel.git/

-- 
Best Regards
Eugeniu Rosca