Linux-Serial Archive on lore.kernel.org
 help / color / Atom feed
From: John Ogness <john.ogness@linutronix.de>
To: linux-kernel@vger.kernel.org
Cc: Peter Zijlstra <peterz@infradead.org>,
	Petr Mladek <pmladek@suse.com>,
	Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com>,
	Steven Rostedt <rostedt@goodmis.org>,
	Daniel Wang <wonderfly@google.com>,
	Andrew Morton <akpm@linux-foundation.org>,
	Linus Torvalds <torvalds@linux-foundation.org>,
	Greg Kroah-Hartman <gregkh@linuxfoundation.org>,
	Alan Cox <gnomes@lxorguk.ukuu.org.uk>,
	Jiri Slaby <jslaby@suse.com>, Peter Feiner <pfeiner@google.com>,
	linux-serial@vger.kernel.org,
	Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
Subject: [RFC PATCH v1 00/25] printk: new implementation
Date: Tue, 12 Feb 2019 15:29:38 +0100
Message-ID: <20190212143003.48446-1-john.ogness@linutronix.de> (raw)

Hello,

As probably many of you are aware, the current printk implementation
has some issues. This series (against 5.0-rc6) makes some fundamental
changes in an attempt to address these issues. The particular issues I
am referring to:

1. The printk buffer is protected by a global raw spinlock for readers
   and writers. This restricts the contexts that are allowed to
   access the buffer.

2. Because of #1, NMI and recursive contexts are handled by deferring
   logging/printing to a spinlock-safe context. This means that
   messages will not be visible if (for example) the kernel dies in
   NMI context and the irq_work mechanism does not survive.

3. Because of #1, when *not* using features such as PREEMPT_RT, large
   latencies exist when printing to slow consoles.

4. Because of #1, when _using_ features such as PREEMPT_RT, printing
   to the consoles is further restricted to contexts that can sleep.
   This can cause large latencies in seeing the messages.

5. Printing to consoles is the responsibility of the printk caller
   and that caller may be required to print many messages that other
   printk callers inserted. Because of this there can be enormous
   variance in the runtime of a printk call.

6. The timestamps on the printk messages are generated when the
   message is inserted into the buffer. But the call to printk may
   have occurred long before that. This is especially true for
   messages in the printk_safe context. This means that printk timing
   information (although neatly "sorted") is neither accurate nor
   reliable.

7. Loglevel INFO is handled the same as ERR. There seems to be an
   endless effort to get printk to show _all_ messages as quickly as
   possible in case of a panic (i.e. printing from any context), but
   at the same time try not to have printk be too intrusive for the
   callers. These are conflicting requirements that lead to a printk
   implementation that does a sub-optimal job of satisfying both
   sides.

To address these issues this series makes the following changes:

- Implements a new printk ringbuffer that supports lockless multiple
  readers. Writers are synchronized per-cpu with support for all
  contexts (including NMI). (This implementation was inspired by a
  post[0] from Peter Zijlstra.)

- The new printk ringbuffer uses the initialized data segment of the
  kernel for its data buffer so that it is available on early boot.

- Timestamps are captured at the beginning of the printk call.

- A dedicated kernel thread is created for printing to all consoles in
  a fully preemptible context.

- A new (optional) console operation "write_atomic" is introduced that
  console drivers may implement. This function must be NMI-safe. An
  implementation for the 8250 UART driver is provided.

- The concept of "emergency messages" is introduced that allows
  important messages (based on a new emergency loglevel threshold) to
  be immediately written to any consoles supporting write_atomic,
  regardless of the context. This allows non-emergency printk calls
  (i.e. INFO) to run in nearly constant time, with their console
  printing taking place in a separate fully preemptible context. And
  emergency messages (i.e. ERR) are printed immediately for the user.

- Individual emergency messages are written contiguously and a CPU-ID
  field is added to all output to allow for sorting of messages being
  printed by multiple CPUs simultaneously.

Although the RFC series works, there are some open issues that I chose
to leave open until I received some initial feedback from the community.
These issues are:

- The behavior of LOG_CONT has been changed. Rather than using the
  current task as the "cont owner", the CPU ID is used. NMIs have
  their own cont buffer so NMI and non-NMI tasks can safely use
  LOG_CONT.

- The runtime resizing features of the printk buffer are not
  implemented.

- The exported vmcore symbols relating to the printk buffer no longer
  exist and no replacements have been defined. I do not know all the
  userspace consequences of making a change here.

- The introduction of the CPU-ID field not only changes the usual
  printk output, but also defines a new field in the extended console
  output. I do not know the userspace consequences of making a change
  here.

- console_flush_on_panic() currently is a NOP. It is pretty clear how
  this could be implemented if atomic_write was available. But if no
  such console is registered, it is not clear what should be done. Is
  this function really even needed?

- Right now the emergency messages are set apart from the
  non-emergency messages using '\n'. There have been requests that
  some special markers could be specifiable to make it easier for
  parsers. Possibly as CONFIG_ and boot options?

- Be aware that printk output is no longer time-sorted. Actually, it
  never was, but now you see the real timestamps. This seems strange
  at first.

- The ringbuffer API is not very pretty. It grew to be what it is
  due to the varying requirements of the different aspects of printk
  (syslog, kmsg_dump, /dev/kmsg, console) and the complexity of
  handling lockless reading, which can fall behind at any moment.

- Memory barriers are not my specialty. A critical eye on their
  usage (or lack thereof) in the ringbuffer code would be greatly
  appreciated.

The first 7 patches introduce the new printk ringbuffer. The
remaining 18 go through and replace the various components of the
printk implementation. All patches are against 5.0-rc6 and each
yield a buildable/testable system.

John Ogness

[0] http://lkml.kernel.org/r/20181017140044.GK3121@hirez.programming.kicks-ass.net

John Ogness (25):
  printk-rb: add printk ring buffer documentation
  printk-rb: add prb locking functions
  printk-rb: define ring buffer struct and initializer
  printk-rb: add writer interface
  printk-rb: add basic non-blocking reading interface
  printk-rb: add blocking reader support
  printk-rb: add functionality required by printk
  printk: add ring buffer and kthread
  printk: remove exclusive console hack
  printk: redirect emit/store to new ringbuffer
  printk_safe: remove printk safe code
  printk: minimize console locking implementation
  printk: track seq per console
  printk: do boot_delay_msec inside printk_delay
  printk: print history for new consoles
  printk: implement CON_PRINTBUFFER
  printk: add processor number to output
  console: add write_atomic interface
  printk: introduce emergency messages
  serial: 8250: implement write_atomic
  printk: implement KERN_CONT
  printk: implement /dev/kmsg
  printk: implement syslog
  printk: implement kmsg_dump
  printk: remove unused code

 Documentation/printk-ringbuffer.txt |  377 +++++++
 drivers/tty/serial/8250/8250.h      |    4 +
 drivers/tty/serial/8250/8250_core.c |   19 +-
 drivers/tty/serial/8250/8250_dma.c  |    5 +-
 drivers/tty/serial/8250/8250_port.c |  154 ++-
 fs/proc/kmsg.c                      |    4 +-
 include/linux/console.h             |    6 +
 include/linux/hardirq.h             |    2 -
 include/linux/kmsg_dump.h           |    6 +-
 include/linux/printk.h              |   30 +-
 include/linux/printk_ringbuffer.h   |  114 +++
 include/linux/serial_8250.h         |    5 +
 init/main.c                         |    1 -
 kernel/kexec_core.c                 |    1 -
 kernel/panic.c                      |    3 -
 kernel/printk/Makefile              |    1 -
 kernel/printk/internal.h            |   79 --
 kernel/printk/printk.c              | 1895 +++++++++++++++++------------------
 kernel/printk/printk_safe.c         |  427 --------
 kernel/trace/trace.c                |    2 -
 lib/Kconfig.debug                   |   17 +
 lib/Makefile                        |    2 +-
 lib/bust_spinlocks.c                |    3 +-
 lib/nmi_backtrace.c                 |    6 -
 lib/printk_ringbuffer.c             |  583 +++++++++++
 25 files changed, 2137 insertions(+), 1609 deletions(-)
 create mode 100644 Documentation/printk-ringbuffer.txt
 create mode 100644 include/linux/printk_ringbuffer.h
 delete mode 100644 kernel/printk/internal.h
 delete mode 100644 kernel/printk/printk_safe.c
 create mode 100644 lib/printk_ringbuffer.c

-- 
2.11.0

             reply index

Thread overview: 147+ messages / expand[flat|nested]  mbox.gz  Atom feed  top
2019-02-12 14:29 John Ogness [this message]
2019-02-12 14:29 ` [RFC PATCH v1 01/25] printk-rb: add printk ring buffer documentation John Ogness
2019-02-12 14:45   ` Greg Kroah-Hartman
2019-02-12 14:29 ` [RFC PATCH v1 02/25] printk-rb: add prb locking functions John Ogness
2019-02-13 15:45   ` Petr Mladek
2019-02-13 21:39     ` John Ogness
2019-02-14 10:33       ` Petr Mladek
2019-02-14 12:10         ` John Ogness
2019-02-15 10:26           ` Petr Mladek
2019-02-15 10:56             ` John Ogness
2019-03-07  2:12   ` Sergey Senozhatsky
2019-02-12 14:29 ` [RFC PATCH v1 03/25] printk-rb: define ring buffer struct and initializer John Ogness
2019-02-12 14:46   ` Greg Kroah-Hartman
2019-02-14 12:46     ` Petr Mladek
2019-02-12 14:29 ` [RFC PATCH v1 04/25] printk-rb: add writer interface John Ogness
2019-02-14 15:16   ` Petr Mladek
2019-02-14 23:36     ` John Ogness
2019-02-15  1:19       ` John Ogness
2019-02-15 13:47       ` Petr Mladek
2019-02-17  1:32         ` John Ogness
2019-02-21 13:51           ` Petr Mladek
2019-02-12 14:29 ` [RFC PATCH v1 05/25] printk-rb: add basic non-blocking reading interface John Ogness
2019-02-18 12:54   ` Petr Mladek
2019-02-19 21:44     ` John Ogness
2019-02-21 16:22       ` Petr Mladek
2019-02-12 14:29 ` [RFC PATCH v1 06/25] printk-rb: add blocking reader support John Ogness
2019-02-18 14:05   ` Petr Mladek
2019-02-19 21:47     ` John Ogness
2019-02-12 14:29 ` [RFC PATCH v1 07/25] printk-rb: add functionality required by printk John Ogness
2019-02-12 17:15   ` Linus Torvalds
2019-02-13  9:20     ` John Ogness
2019-02-18 15:59   ` Petr Mladek
2019-02-19 22:08     ` John Ogness
2019-02-22  9:58       ` Petr Mladek
2019-02-12 14:29 ` [RFC PATCH v1 08/25] printk: add ring buffer and kthread John Ogness
2019-02-12 15:47   ` Sergey Senozhatsky
2019-02-19 13:54   ` Petr Mladek
2019-03-04  7:38   ` Sergey Senozhatsky
2019-03-04 10:00     ` Sergey Senozhatsky
2019-03-04 11:07       ` Sergey Senozhatsky
2019-03-05 21:00         ` John Ogness
2019-03-06 15:57           ` Petr Mladek
2019-03-06 21:17             ` John Ogness
2019-03-06 22:22               ` John Ogness
2019-03-07  6:41                 ` Sergey Senozhatsky
2019-03-07  6:51                   ` Sergey Senozhatsky
2019-03-07 12:50               ` Petr Mladek
2019-03-07  5:15           ` Sergey Senozhatsky
2019-03-11 10:51             ` John Ogness
2019-03-12  9:58               ` Sergey Senozhatsky
2019-03-12 10:30               ` Petr Mladek
2019-03-07 12:06     ` John Ogness
2019-03-08  1:31       ` Sergey Senozhatsky
2019-03-08 10:04         ` Petr Mladek
2019-02-12 14:29 ` [RFC PATCH v1 09/25] printk: remove exclusive console hack John Ogness
2019-02-19 14:03   ` Petr Mladek
2019-02-12 14:29 ` [RFC PATCH v1 10/25] printk: redirect emit/store to new ringbuffer John Ogness
2019-02-20  9:01   ` Petr Mladek
2019-02-20 21:25     ` John Ogness
2019-02-22 14:43       ` Petr Mladek
2019-02-22 15:06         ` John Ogness
2019-02-22 15:25           ` Petr Mladek
2019-02-25 12:11       ` Petr Mladek
2019-02-25 16:41         ` John Ogness
2019-02-26  9:45           ` Petr Mladek
2019-02-12 14:29 ` [RFC PATCH v1 11/25] printk_safe: remove printk safe code John Ogness
2019-02-22 10:37   ` Petr Mladek
2019-02-22 13:38     ` John Ogness
2019-02-22 15:15       ` Petr Mladek
2019-02-12 14:29 ` [RFC PATCH v1 12/25] printk: minimize console locking implementation John Ogness
2019-02-25 13:44   ` Petr Mladek
2019-02-12 14:29 ` [RFC PATCH v1 13/25] printk: track seq per console John Ogness
2019-02-25 14:59   ` Petr Mladek
2019-02-26  8:45     ` John Ogness
2019-02-26 13:11       ` Petr Mladek
2019-02-12 14:29 ` [RFC PATCH v1 14/25] printk: do boot_delay_msec inside printk_delay John Ogness
2019-02-12 14:29 ` [RFC PATCH v1 15/25] printk: print history for new consoles John Ogness
2019-02-26 14:58   ` Petr Mladek
2019-02-26 15:22     ` John Ogness
2019-02-27  9:02       ` Petr Mladek
2019-02-27 10:02         ` John Ogness
2019-02-27 13:12           ` Petr Mladek
2019-03-04  9:24       ` Sergey Senozhatsky
2019-02-12 14:29 ` [RFC PATCH v1 16/25] printk: implement CON_PRINTBUFFER John Ogness
2019-02-26 15:38   ` Petr Mladek
2019-02-12 14:29 ` [RFC PATCH v1 17/25] printk: add processor number to output John Ogness
2019-02-13 22:29   ` John Ogness
2019-02-12 14:29 ` [RFC PATCH v1 18/25] console: add write_atomic interface John Ogness
2019-02-12 14:29 ` [RFC PATCH v1 19/25] printk: introduce emergency messages John Ogness
2019-03-07  7:30   ` Sergey Senozhatsky
2019-03-08 10:31     ` Petr Mladek
2019-03-11 12:04       ` John Ogness
2019-03-12  2:51         ` Sergey Senozhatsky
2019-03-12  2:58       ` Sergey Senozhatsky
2019-02-12 14:29 ` [RFC PATCH v1 20/25] serial: 8250: implement write_atomic John Ogness
2019-02-27  9:46   ` Petr Mladek
2019-02-27 10:32     ` John Ogness
2019-02-27 13:55       ` Petr Mladek
2019-03-08  4:05         ` John Ogness
2019-03-08  4:17           ` John Ogness
2019-03-08 10:28           ` Petr Mladek
2019-02-12 14:29 ` [RFC PATCH v1 21/25] printk: implement KERN_CONT John Ogness
2019-02-12 14:30 ` [RFC PATCH v1 22/25] printk: implement /dev/kmsg John Ogness
2019-02-12 14:30 ` [RFC PATCH v1 23/25] printk: implement syslog John Ogness
2019-02-12 14:30 ` [RFC PATCH v1 24/25] printk: implement kmsg_dump John Ogness
2019-02-12 14:30 ` [RFC PATCH v1 25/25] printk: remove unused code John Ogness
2019-03-08 14:02   ` Sebastian Andrzej Siewior
2019-03-11  2:46     ` Sergey Senozhatsky
2019-03-11  8:18       ` Sebastian Andrzej Siewior
2019-03-12  9:38         ` Petr Mladek
2019-02-13  1:31 ` [RFC PATCH v1 00/25] printk: new implementation Sergey Senozhatsky
2019-02-13 13:43   ` John Ogness
2019-03-04  6:39     ` Sergey Senozhatsky
2019-02-13  1:41 ` Sergey Senozhatsky
2019-02-13 14:15   ` John Ogness
2019-03-04  5:31     ` Sergey Senozhatsky
2019-02-13  2:55 ` Sergey Senozhatsky
2019-02-13 14:43   ` John Ogness
2019-03-04  5:23     ` Sergey Senozhatsky
2019-03-07  9:53       ` John Ogness
2019-03-08 10:00         ` Petr Mladek
2019-03-11 10:54         ` Sergey Senozhatsky
2019-03-12 12:38           ` Petr Mladek
2019-03-12 15:15             ` John Ogness
2019-03-13  2:15               ` Sergey Senozhatsky
2019-03-13  8:19                 ` John Ogness
2019-03-13  8:40                   ` Sebastian Siewior
2019-03-13  9:27                     ` Sergey Senozhatsky
2019-03-13 10:06                       ` Sergey Senozhatsky
2019-03-14  9:27                       ` Petr Mladek
2019-03-13  8:46                   ` Sergey Senozhatsky
2019-03-14  9:14               ` Petr Mladek
2019-03-14  9:35                 ` John Ogness
2019-03-13  2:00             ` Sergey Senozhatsky
2019-02-13 16:54 ` David Laight
2019-02-13 22:20   ` John Ogness
2020-01-20 23:05 ` Eugeniu Rosca
2020-01-21 23:56   ` John Ogness
2020-01-22  2:34     ` Eugeniu Rosca
2020-01-22  7:31       ` Geert Uytterhoeven
2020-01-22 16:58         ` Eugeniu Rosca
2020-01-22 19:48           ` Geert Uytterhoeven
2020-01-24 16:09             ` Eugeniu Rosca
2020-01-27 12:32               ` Petr Mladek
2020-01-27 13:45                 ` Eugeniu Rosca
2020-01-22 10:33       ` John Ogness
2020-01-24 12:13         ` Eugeniu Rosca

Reply instructions:

You may reply publicly to this message via plain-text email
using any one of the following methods:

* Save the following mbox file, import it into your mail client,
  and reply-to-all from there: mbox

  Avoid top-posting and favor interleaved quoting:
  https://en.wikipedia.org/wiki/Posting_style#Interleaved_style

* Reply using the --to, --cc, and --in-reply-to
  switches of git-send-email(1):

  git send-email \
    --in-reply-to=20190212143003.48446-1-john.ogness@linutronix.de \
    --to=john.ogness@linutronix.de \
    --cc=akpm@linux-foundation.org \
    --cc=gnomes@lxorguk.ukuu.org.uk \
    --cc=gregkh@linuxfoundation.org \
    --cc=jslaby@suse.com \
    --cc=linux-kernel@vger.kernel.org \
    --cc=linux-serial@vger.kernel.org \
    --cc=peterz@infradead.org \
    --cc=pfeiner@google.com \
    --cc=pmladek@suse.com \
    --cc=rostedt@goodmis.org \
    --cc=sergey.senozhatsky.work@gmail.com \
    --cc=sergey.senozhatsky@gmail.com \
    --cc=torvalds@linux-foundation.org \
    --cc=wonderfly@google.com \
    /path/to/YOUR_REPLY

  https://kernel.org/pub/software/scm/git/docs/git-send-email.html

* If your mail client supports setting the In-Reply-To header
  via mailto: links, try the mailto: link

Linux-Serial Archive on lore.kernel.org

Archives are clonable:
	git clone --mirror https://lore.kernel.org/linux-serial/0 linux-serial/git/0.git

	# If you have public-inbox 1.1+ installed, you may
	# initialize and index your mirror using the following commands:
	public-inbox-init -V2 linux-serial linux-serial/ https://lore.kernel.org/linux-serial \
		linux-serial@vger.kernel.org
	public-inbox-index linux-serial

Example config snippet for mirrors

Newsgroup available over NNTP:
	nntp://nntp.lore.kernel.org/org.kernel.vger.linux-serial


AGPL code for this site: git clone https://public-inbox.org/public-inbox.git