Re: [Ksummit-discuss] [TECH TOPIC] printk redesign

[Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com>]

Hello,

On (07/19/17 09:35), David Woodhouse wrote:
[..]
> > At some point we start reinventing ftrace...  there's issues with
> > joining the two up but there should at least be lessons we can learn.
> > 
> 
> The other way of looking at this is "why are you abusing printk for
> stuff that should have been done via ftrace or other means instead".
>
> I confess I haven't got my curmudgeonly brain out of that mode at all,
> ever since realising that printk had been made asynchronous and
> unreliable (how long ago was that?) and that you could no longer see
> the dying gasp of a crashing kernel on its serial console.
> 
> Rather than morphing printk into something more capable of bulk
> transport, I'd rather see it go back to its roots of
> debugging/diagnostics.
> 
> The original complaint of "all this printk output makes things too
> slow" was better addressed by printing less or at lower severity (or
> adjusting the console loglevel), IMO.
> 
> As things stand, the requirements for the various printk (ab)use cases
> seem to be contradictory — if we're going to have a redesign then I
> think it would be good to take a holistic view and decide what it's
> actually *supposed* to be used for. And, perhaps more to the point,
> what it isn't supposed to be used for.

just some thoughts,

at glance printk has 3 major issues

- it has to do offloading, no doubt.

- printk() can deadlock, easily. (that's the whole reason there is
  printk_deferred())

- printk from NMI is not completely reliable. this area has been
  improved recently; but there are still cases when we can lose
  NMI-printk messages


... but there are more problems. and those issues are not completely
printk fault.

what I mean (and I'm not criticizing anyone),

so we can split printk: defer printing of debug messages and have
direct printing of important messages. and that's where the redesign
hits the first obstacle: direct printing is unreliable. when we do
call_console_drivers() we pass control to the outside world, and we
never know where we will end up at. consoles can invoke timekeeping,
networking, MM, and so on. so I think printk redesign better start
from this part - make call to console drivers more reliable.
if possible.


what I'm talking about, by just one example:

bug report
https://marc.info/?l=dri-devel&m=149938825811219

root cause
https://marc.info/?l=linux-mm&m=149939515214223&w=2


so printk live-locked, and there was no way to see any kernel logs
until Tetsuo sysrq-c'ed the system. and the root cause was all those
complex and difficult dependencies between completely different
subsystems that printk depend on and that, in turn, depend on printk.


> hm, this allocation, per se, looks ok to me. can't really blame it.
> what you had is a combination of factors
>
>        CPU0                    CPU1                            CPU2
>                                                                console_callback()
>                                                                 console_lock()
>                                                                 ^^^^^^^^^^^^^
>        vprintk_emit()          mutex_lock(&par->bo_mutex)
>                                 kzalloc(GFP_KERNEL)
>         console_trylock()        kmem_cache_alloc()              mutex_lock(&par->bo_mutex)
>         ^^^^^^^^^^^^^^^^          io_schedule_timeout


there are more examples.

more closer to the point,
to the best of my knowledge, we don't have that much problems with the
printk logbuf now. we made some progress there over the last year. yes,
NMI printk is not completely awesome.
where we do have problems, I think:

a) we probably need to make more progress towards "and now we print it to the console"
b) print out offloading
c) printk deadlock and the need of printk_deferred()



and it's not always crazy printk abuse to justify the existence of
printk offloading.

example: https://marc.info/?l=linux-mm&m=149977866327662

> you will find that calling cond_resched() (from console_unlock() from printk())
> can cause a delay of nearly one minute, and it can cause a delay of nearly 5 minutes
> to complete one out_of_memory() call. 

example: https://marc.info/?l=linux-kernel&m=149509270422321


printk, to me, is a debugging/diagnostics tool. and we can't fully rely on
it, even we do reasonable things, like OOM print out. moreover, I think, to
some extent, due to printk imperfections, the more debugging options we
enable (CONFIG_DEBUG_PREEMPT, CONFIG_DEBUG_SPINLOCK, etc.) the less stable
the kernel, potentially, gets. because those options use printk() to report
the problems. so might_sleep() or spin_dump() called from "a wrong place"
can eventually deadlock printk() and the system.

example: https://marc.info/?l=linux-kernel&m=149007148320611


well, just my thoughts.

	-ss