All of lore.kernel.org
 help / color / mirror / Atom feed
* [RFC][PATCHv5 00/13] printk: introduce printing kernel thread
@ 2017-08-15  2:56 Sergey Senozhatsky
  2017-08-15  2:56 ` [RFC][PATCHv5 01/13] printk: move printk_pending out of per-cpu Sergey Senozhatsky
                   ` (14 more replies)
  0 siblings, 15 replies; 94+ messages in thread
From: Sergey Senozhatsky @ 2017-08-15  2:56 UTC (permalink / raw)
  To: Petr Mladek, Steven Rostedt
  Cc: Jan Kara, Andrew Morton, Peter Zijlstra, Rafael J . Wysocki,
	Eric Biederman, Greg Kroah-Hartman, Jiri Slaby, Pavel Machek,
	Andreas Mohr, Tetsuo Handa, linux-kernel, Sergey Senozhatsky,
	Sergey Senozhatsky

Hello,

        RFC

        This patch set adds a printk() kernel thread which let us
to print kernel messages to the console from a non-atomic/schedule-able
context, avoiding different sort of lockups, stalls, etc.

        Offloading threshold is now in "seconds spent in console_unlock()",
not in "lines printed", this lets us to be a little bit more 'watchdog-aware'
in printk. But we still can (and probably must) do better, tho. May be there
will be a new watchdog API some day, so will be able to make better decisions
in printk.

        And a whole bunch of other improvements and tweaks. Like preemption
in console_unlock(), and so on. Any comments and thoughts are appreciated.


v4->v5
-- split some of the patches
-- make offloading time-based (not number of lines printed)
-- move offloading control to per-CPU
-- remove a pessimistic offloading spin from console_unlock()
-- adjust printk_kthread CPU affinity mask
-- disable preemption in console_unlock()
-- always offload printing from user space processes
-- add sync version of emergency_begin API
-- offload from printk_kthread as well, to periodically up() console_sem
-- limit `atomic_print_limit' to `watchdog_thresh'
-- and some other changes...

v3->v4 (Petr, Jan)
-- add syscore notifiers
-- fix 0001 compilation warnings
-- use proper CPU notifiers return values

v2->v3 (Petr, Pavel, Andreas):
-- rework offloading
-- use PM notifiers
-- dropped some patches, etc. etc.

v1->v2:
-- introduce printk_emergency mode and API to switch it on/off
-- move printk_pending out of per-CPU memory
-- add printk emergency_mode sysfs node
-- switch sysrq handlers (some of them) to printk_emergency
-- cleanus/etc.

Sergey Senozhatsky (13):
  printk: move printk_pending out of per-cpu
  printk: introduce printing kernel thread
  printk: add sync printk_emergency API
  printk: add enforce_emergency parameter
  printk: enable printk offloading
  printk: register PM notifier
  printk: register syscore notifier
  printk: set watchdog_thresh as maximum value for atomic_print_limit
  printk: add auto-emergency enforcement mechanism
  printk: force printk_kthread to offload printing
  printk: always offload printing from user-space processes
  printk: do not cond_resched() when we can offload
  printk: move offloading logic to per-cpu

 Documentation/admin-guide/kernel-parameters.txt |  17 +
 include/linux/console.h                         |   5 +
 kernel/printk/printk.c                          | 435 ++++++++++++++++++++++--
 3 files changed, 433 insertions(+), 24 deletions(-)

-- 
2.14.1

^ permalink raw reply	[flat|nested] 94+ messages in thread

* [RFC][PATCHv5 01/13] printk: move printk_pending out of per-cpu
  2017-08-15  2:56 [RFC][PATCHv5 00/13] printk: introduce printing kernel thread Sergey Senozhatsky
@ 2017-08-15  2:56 ` Sergey Senozhatsky
  2017-08-15  2:56 ` [RFC][PATCHv5 02/13] printk: introduce printing kernel thread Sergey Senozhatsky
                   ` (13 subsequent siblings)
  14 siblings, 0 replies; 94+ messages in thread
From: Sergey Senozhatsky @ 2017-08-15  2:56 UTC (permalink / raw)
  To: Petr Mladek, Steven Rostedt
  Cc: Jan Kara, Andrew Morton, Peter Zijlstra, Rafael J . Wysocki,
	Eric Biederman, Greg Kroah-Hartman, Jiri Slaby, Pavel Machek,
	Andreas Mohr, Tetsuo Handa, linux-kernel, Sergey Senozhatsky,
	Sergey Senozhatsky

Do not keep `printk_pending' in per-CPU area. We set the following bits
of printk_pending:
a) PRINTK_PENDING_WAKEUP
	when we need to wakeup klogd
b) PRINTK_PENDING_OUTPUT
	when there is a pending output from deferred printk and we need
	to call console_unlock().

So none of the bits control/represent a state of a particular CPU and,
basically, they should be global instead.

Besides we will use `printk_pending' to control printk kthread, so this
patch is also a preparation work.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
Suggested-by: Petr Mladek <pmladek@suse.com>
---
 kernel/printk/printk.c | 26 ++++++++++++--------------
 1 file changed, 12 insertions(+), 14 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 290b548e9fa9..8777003d292e 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -401,6 +401,14 @@ DEFINE_RAW_SPINLOCK(logbuf_lock);
 	} while (0)
 
 #ifdef CONFIG_PRINTK
+/*
+ * Delayed printk version, for scheduler-internal messages:
+ */
+#define PRINTK_PENDING_WAKEUP	0x01
+#define PRINTK_PENDING_OUTPUT	0x02
+
+static unsigned long printk_pending;
+
 DECLARE_WAIT_QUEUE_HEAD(log_wait);
 /* the next printk record to read by syslog(READ) or /proc/kmsg */
 static u64 syslog_seq;
@@ -2688,25 +2696,15 @@ static int __init printk_late_init(void)
 late_initcall(printk_late_init);
 
 #if defined CONFIG_PRINTK
-/*
- * Delayed printk version, for scheduler-internal messages:
- */
-#define PRINTK_PENDING_WAKEUP	0x01
-#define PRINTK_PENDING_OUTPUT	0x02
-
-static DEFINE_PER_CPU(int, printk_pending);
-
 static void wake_up_klogd_work_func(struct irq_work *irq_work)
 {
-	int pending = __this_cpu_xchg(printk_pending, 0);
-
-	if (pending & PRINTK_PENDING_OUTPUT) {
+	if (test_and_clear_bit(PRINTK_PENDING_OUTPUT, &printk_pending)) {
 		/* If trylock fails, someone else is doing the printing */
 		if (console_trylock())
 			console_unlock();
 	}
 
-	if (pending & PRINTK_PENDING_WAKEUP)
+	if (test_and_clear_bit(PRINTK_PENDING_WAKEUP, &printk_pending))
 		wake_up_interruptible(&log_wait);
 }
 
@@ -2719,7 +2717,7 @@ void wake_up_klogd(void)
 {
 	preempt_disable();
 	if (waitqueue_active(&log_wait)) {
-		this_cpu_or(printk_pending, PRINTK_PENDING_WAKEUP);
+		set_bit(PRINTK_PENDING_WAKEUP, &printk_pending);
 		irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
 	}
 	preempt_enable();
@@ -2732,7 +2730,7 @@ int vprintk_deferred(const char *fmt, va_list args)
 	r = vprintk_emit(0, LOGLEVEL_SCHED, NULL, 0, fmt, args);
 
 	preempt_disable();
-	__this_cpu_or(printk_pending, PRINTK_PENDING_OUTPUT);
+	set_bit(PRINTK_PENDING_OUTPUT, &printk_pending);
 	irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
 	preempt_enable();
 
-- 
2.14.1

^ permalink raw reply	[flat|nested] 94+ messages in thread

* [RFC][PATCHv5 02/13] printk: introduce printing kernel thread
  2017-08-15  2:56 [RFC][PATCHv5 00/13] printk: introduce printing kernel thread Sergey Senozhatsky
  2017-08-15  2:56 ` [RFC][PATCHv5 01/13] printk: move printk_pending out of per-cpu Sergey Senozhatsky
@ 2017-08-15  2:56 ` Sergey Senozhatsky
  2017-08-15  2:56 ` [RFC][PATCHv5 03/13] printk: add sync printk_emergency API Sergey Senozhatsky
                   ` (12 subsequent siblings)
  14 siblings, 0 replies; 94+ messages in thread
From: Sergey Senozhatsky @ 2017-08-15  2:56 UTC (permalink / raw)
  To: Petr Mladek, Steven Rostedt
  Cc: Jan Kara, Andrew Morton, Peter Zijlstra, Rafael J . Wysocki,
	Eric Biederman, Greg Kroah-Hartman, Jiri Slaby, Pavel Machek,
	Andreas Mohr, Tetsuo Handa, linux-kernel, Sergey Senozhatsky,
	Sergey Senozhatsky

printk() is quite complex internally and, basically, it does two
slightly independent things:
 a) adds a new message to a kernel log buffer (log_store())
 b) prints kernel log messages to serial consoles (console_unlock())

while (a) is guaranteed to be executed by printk(), (b) is not, for a
variety of reasons, and, unlike log_store(), it comes at a price:

 1) console_unlock() attempts to flush all pending kernel log messages
to the console and it can loop indefinitely.

 2) while console_unlock() is executed on one particular CPU, printing
pending kernel log messages, other CPUs can simultaneously append new
messages to the kernel log buffer.

 3) the time it takes console_unlock() to print kernel messages also
depends on the speed of the console -- which may not be fast at all.

 4) console_unlock() is executed in the same context as printk(), so
it may be non-preemptible/atomic, which makes 1)-3) dangerous.

As a result, nobody knows how long a printk() call will take, so
it's not really safe to call printk() in a number of situations,
including atomic context, RCU critical sections, interrupt context,
etc.

This patch introduces a '/sys/module/printk/parameters/atomic_print_limit'
sysfs param, which sets the limit on the number of seconds a given process
can print from console_unlock(). Value 0 corresponds to the current behavior
(no limitation). The printing offloading is happening from console_unlock()
function and, briefly, looks as follows:
	as soon as process prints for more than `atomic_print_limit' seconds
it attempts to offload printing to another process.

Since nothing guarantees that there will another process sleeping on the
console_sem or calling printk() on another CPU simultaneously, the patch
also introduces auxiliary kernel thread - printk_kthread, the main
purpose of which is to take over printing duty. The workflow is, thus,
turns into:
	as soon as process prints for more than `atomic_print_limit' seconds
it wakes up printk_kthread and unlocks the console_sem.

The wakeup part is also a bit tricky, since scheduler is in position to
decide that printk_kthread should run on the very same CPU with the process
that is currently doing printing. This means that offloading potentially
may never take place. That's why we try to play games with printk_kthread
affinity mask and basically want to wake it up on a foreign CPU, so
printing take over has more chances to succeed.

There are, however, cases when we can't (or should not) offload. For
example, we can't call into the scheduler from panic(), because this
may cause deadlock. Therefore printk() has a new 'emergency mode': in
this mode we never attempt to offload printing to printk_kthread.
There are places, where printk switches to printk_emergency mode
automatically: for instance, once a EMERG log level message appears
in the log buffer; in others - user must explicitly forbid offloading.
For that purpose we provide two new functions:

 -- printk_emergency_begin()
    Disables printk offloading. All printk() calls (except for deferred
    printk) will attempt to lock the console_sem and, if successful,
    flush kernel log messages.

 -- printk_emergency_end()
    Enables printk offloading.

Offloading is not possible yet, it will be enabled in a later patch.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 Documentation/admin-guide/kernel-parameters.txt |  10 ++
 include/linux/console.h                         |   3 +
 kernel/printk/printk.c                          | 184 ++++++++++++++++++++++--
 3 files changed, 185 insertions(+), 12 deletions(-)

diff --git a/Documentation/admin-guide/kernel-parameters.txt b/Documentation/admin-guide/kernel-parameters.txt
index 35a31ea1d709..b5b6d5d24596 100644
--- a/Documentation/admin-guide/kernel-parameters.txt
+++ b/Documentation/admin-guide/kernel-parameters.txt
@@ -3205,6 +3205,16 @@
 	printk.time=	Show timing data prefixed to each printk message line
 			Format: <bool>  (1/Y/y=enable, 0/N/n=disable)
 
+	printk.atomic_print_limit=
+			Specify the number of seconds a particular task
+			can spend printing messages to the console before
+			it offloads its printing duty to a special printk
+			kthread. Normally the limit should not be larger
+			than watchdog lockup detection threshold. Setting
+			this parameter to 0 disables printing offloading.
+
+			default: off.
+
 	processor.max_cstate=	[HW,ACPI]
 			Limit processor to maximum C-state
 			max_cstate=9 overrides any DMI blacklist limit.
diff --git a/include/linux/console.h b/include/linux/console.h
index b8920a031a3e..07005db4c788 100644
--- a/include/linux/console.h
+++ b/include/linux/console.h
@@ -187,6 +187,9 @@ extern bool console_suspend_enabled;
 extern void suspend_console(void);
 extern void resume_console(void);
 
+extern void printk_emergency_begin(void);
+extern void printk_emergency_end(void);
+
 int mda_console_init(void);
 void prom_con_init(void);
 
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 8777003d292e..a86767d4d619 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -48,6 +48,7 @@
 #include <linux/sched/clock.h>
 #include <linux/sched/debug.h>
 #include <linux/sched/task_stack.h>
+#include <linux/kthread.h>
 
 #include <linux/uaccess.h>
 #include <asm/sections.h>
@@ -400,15 +401,16 @@ DEFINE_RAW_SPINLOCK(logbuf_lock);
 		printk_safe_exit_irqrestore(flags);	\
 	} while (0)
 
-#ifdef CONFIG_PRINTK
 /*
- * Delayed printk version, for scheduler-internal messages:
+ * Used both for deferred printk version (scheduler-internal messages)
+ * and printk_kthread control.
  */
 #define PRINTK_PENDING_WAKEUP	0x01
 #define PRINTK_PENDING_OUTPUT	0x02
 
 static unsigned long printk_pending;
 
+#ifdef CONFIG_PRINTK
 DECLARE_WAIT_QUEUE_HEAD(log_wait);
 /* the next printk record to read by syslog(READ) or /proc/kmsg */
 static u64 syslog_seq;
@@ -444,6 +446,127 @@ static char __log_buf[__LOG_BUF_LEN] __aligned(LOG_ALIGN);
 static char *log_buf = __log_buf;
 static u32 log_buf_len = __LOG_BUF_LEN;
 
+static struct task_struct *printk_kthread;
+static cpumask_var_t printk_offload_cpus;
+/*
+ * We can't call into the scheduler (wake_up() printk kthread) during
+ * suspend/kexec/etc. This temporarily switches printk to old behaviour.
+ */
+static atomic_t printk_emergency __read_mostly;
+/*
+ * Disable printk_kthread permanently. Unlike `oops_in_progress'
+ * it doesn't go back to 0.
+ */
+static bool printk_enforce_emergency __read_mostly;
+/*
+ * The number of seconds a task can print before it offloads printing
+ * duty to printk_kthread. 0 indicates 'no limit'.
+ */
+static unsigned int atomic_print_limit;
+
+module_param_named(atomic_print_limit, atomic_print_limit, uint, 0644);
+MODULE_PARM_DESC(atomic_print_limit,
+		 "the number of seconds task is allowed to print messages");
+
+static inline bool printk_offloading_enabled(void)
+{
+	return atomic_print_limit &&
+		printk_enforce_emergency == 0 &&
+		printk_kthread &&
+		atomic_read(&printk_emergency) == 0;
+}
+
+static inline bool is_printk_offloading_safe(void)
+{
+	return system_state == SYSTEM_RUNNING && !oops_in_progress;
+}
+
+static inline bool printk_kthread_should_stop(void)
+{
+	if (current != printk_kthread)
+		return false;
+	/* An emergency mode */
+	return (atomic_read(&printk_emergency) != 0);
+}
+
+/*
+ * This disables printing offloading and instead attempts
+ * to do the usual console_trylock()->console_unlock().
+ *
+ * Note, this does not wait for printk_kthread to stop (if it's
+ * already printing logbuf messages).
+ */
+void printk_emergency_begin(void)
+{
+	atomic_inc(&printk_emergency);
+}
+EXPORT_SYMBOL_GPL(printk_emergency_begin);
+
+/* This re-enables printk_kthread offloading. */
+void printk_emergency_end(void)
+{
+	atomic_dec(&printk_emergency);
+}
+EXPORT_SYMBOL_GPL(printk_emergency_end);
+
+/*
+ * Under heavy printing load or with a slow serial console (or both)
+ * console_unlock() can stall CPUs, which can result in soft/hard-lockups,
+ * lost interrupts, RCU stalls, etc. Therefore we attempt to limit the
+ * amount of time a process can print from console_unlock().
+ *
+ * This function must be called from 'printk_safe' context under
+ * console_sem lock.
+ */
+static inline bool console_offload_printing(void)
+{
+	static struct task_struct *printing_task;
+	static unsigned long printing_start_ts;
+	unsigned long now = local_clock() >> 30LL; /* seconds */
+
+	if (printk_kthread_should_stop())
+		return true;
+
+	if (!printk_offloading_enabled())
+		return false;
+
+	if (!is_printk_offloading_safe())
+		return false;
+
+	/* A new task - reset the counters. */
+	if (printing_task != current) {
+		printing_start_ts = local_clock() >> 30LL;
+		printing_task = current;
+		return false;
+	}
+
+	/* Once we offloaded to printk_ktread - keep printing */
+	if (current == printk_kthread)
+		return false;
+
+	if (!time_after_eq(now, printing_start_ts + atomic_print_limit))
+		return false;
+
+	/*
+	 * We try to set `printk_kthread' CPU affinity to any online CPU
+	 * except for this_cpu. Because otherwise `printk_kthread' may be
+	 * scheduled on the same CPU and offloading will not take place.
+	 */
+	cpumask_copy(printk_offload_cpus, cpu_online_mask);
+	cpumask_clear_cpu(smp_processor_id(), printk_offload_cpus);
+
+	/*
+	 * If this_cpu is the one and only online CPU, then try to wake up
+	 * `printk_kthread' on it.
+	 */
+	if (cpumask_empty(printk_offload_cpus))
+		cpumask_set_cpu(smp_processor_id(), printk_offload_cpus);
+
+	set_cpus_allowed_ptr(printk_kthread, printk_offload_cpus);
+	wake_up_process(printk_kthread);
+	return true;
+}
+
 /* Return log buffer address */
 char *log_buf_addr_get(void)
 {
@@ -1763,6 +1886,15 @@ asmlinkage int vprintk_emit(int facility, int level,
 
 	printed_len = log_output(facility, level, lflags, dict, dictlen, text, text_len);
 
+	/*
+	 * Emergency level indicates that the system is unstable and, thus,
+	 * we better stop relying on wake_up(printk_kthread) and try to do
+	 * a direct printing.
+	 */
+	if (level == LOGLEVEL_EMERG)
+		printk_enforce_emergency = true;
+
+	set_bit(PRINTK_PENDING_OUTPUT, &printk_pending);
 	logbuf_unlock_irqrestore(flags);
 
 	/* If called from the scheduler, we can not call up(). */
@@ -1880,6 +2012,14 @@ static size_t msg_print_text(const struct printk_log *msg,
 			     bool syslog, char *buf, size_t size) { return 0; }
 static bool suppress_message_printing(int level) { return false; }
 
+void printk_emergency_begin(void) {}
+EXPORT_SYMBOL_GPL(printk_emergency_begin);
+
+void printk_emergency_end(void) {}
+EXPORT_SYMBOL_GPL(printk_emergency_end);
+
+static inline bool console_offload_printing(void) { return false; }
+
 #endif /* CONFIG_PRINTK */
 
 #ifdef CONFIG_EARLY_PRINTK
@@ -2161,8 +2301,17 @@ void console_unlock(void)
 	unsigned long flags;
 	bool wake_klogd = false;
 	bool do_cond_resched, retry;
+	bool did_offload;
 
 	if (console_suspended) {
+		/*
+		 * Here and later, we need to clear the PENDING_OUTPUT bit
+		 * in order to avoid an infinite loop in printk_kthread
+		 * function when console_unlock() cannot flush messages
+		 * because we suspended consoles. Someone else will print
+		 * the messages from resume_console().
+		 */
+		clear_bit(PRINTK_PENDING_OUTPUT, &printk_pending);
 		up_console_sem();
 		return;
 	}
@@ -2191,6 +2340,7 @@ void console_unlock(void)
 	 * console.
 	 */
 	if (!can_use_console()) {
+		clear_bit(PRINTK_PENDING_OUTPUT, &printk_pending);
 		console_locked = 0;
 		up_console_sem();
 		return;
@@ -2202,6 +2352,9 @@ void console_unlock(void)
 		size_t len;
 
 		printk_safe_enter_irqsave(flags);
+		/* Must be called under printk_safe */
+		did_offload = console_offload_printing();
+
 		raw_spin_lock(&logbuf_lock);
 		if (seen_seq != log_next_seq) {
 			wake_klogd = true;
@@ -2219,7 +2372,7 @@ void console_unlock(void)
 			len = 0;
 		}
 skip:
-		if (console_seq == log_next_seq)
+		if (did_offload || console_seq == log_next_seq)
 			break;
 
 		msg = log_from_idx(console_idx);
@@ -2267,14 +2420,18 @@ void console_unlock(void)
 	up_console_sem();
 
 	/*
-	 * Someone could have filled up the buffer again, so re-check if there's
-	 * something to flush. In case we cannot trylock the console_sem again,
-	 * there's a new owner and the console_unlock() from them will do the
-	 * flush, no worries.
+	 * Someone could have filled up the buffer again, so re-check
+	 * if there's something to flush. In case when trylock fails,
+	 * there's a new owner and the console_unlock() from them will
+	 * do the flush, no worries.
 	 */
-	raw_spin_lock(&logbuf_lock);
-	retry = console_seq != log_next_seq;
-	raw_spin_unlock(&logbuf_lock);
+	if (!did_offload) {
+		raw_spin_lock(&logbuf_lock);
+		retry = console_seq != log_next_seq;
+		if (!retry)
+			clear_bit(PRINTK_PENDING_OUTPUT, &printk_pending);
+		raw_spin_unlock(&logbuf_lock);
+	}
 	printk_safe_exit_irqrestore(flags);
 
 	if (retry && console_trylock())
@@ -2698,8 +2855,11 @@ late_initcall(printk_late_init);
 #if defined CONFIG_PRINTK
 static void wake_up_klogd_work_func(struct irq_work *irq_work)
 {
-	if (test_and_clear_bit(PRINTK_PENDING_OUTPUT, &printk_pending)) {
-		/* If trylock fails, someone else is doing the printing */
+	if (test_bit(PRINTK_PENDING_OUTPUT, &printk_pending)) {
+		/*
+		 * If trylock fails, someone else is doing the printing.
+		 * PRINTK_PENDING_OUTPUT bit is cleared by console_unlock().
+		 */
 		if (console_trylock())
 			console_unlock();
 	}
-- 
2.14.1

^ permalink raw reply	[flat|nested] 94+ messages in thread

* [RFC][PATCHv5 03/13] printk: add sync printk_emergency API
  2017-08-15  2:56 [RFC][PATCHv5 00/13] printk: introduce printing kernel thread Sergey Senozhatsky
  2017-08-15  2:56 ` [RFC][PATCHv5 01/13] printk: move printk_pending out of per-cpu Sergey Senozhatsky
  2017-08-15  2:56 ` [RFC][PATCHv5 02/13] printk: introduce printing kernel thread Sergey Senozhatsky
@ 2017-08-15  2:56 ` Sergey Senozhatsky
  2017-08-15  2:56 ` [RFC][PATCHv5 04/13] printk: add enforce_emergency parameter Sergey Senozhatsky
                   ` (11 subsequent siblings)
  14 siblings, 0 replies; 94+ messages in thread
From: Sergey Senozhatsky @ 2017-08-15  2:56 UTC (permalink / raw)
  To: Petr Mladek, Steven Rostedt
  Cc: Jan Kara, Andrew Morton, Peter Zijlstra, Rafael J . Wysocki,
	Eric Biederman, Greg Kroah-Hartman, Jiri Slaby, Pavel Machek,
	Andreas Mohr, Tetsuo Handa, linux-kernel, Sergey Senozhatsky,
	Sergey Senozhatsky

We already have `async' printk_emergency_begin(), which returns
immediately and does not guarantee that `printk_kthread' will
stop by the time it returns. Add `sync' version, which waits for
`printk_kthread' to stop.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 include/linux/console.h |  2 ++
 kernel/printk/printk.c  | 38 ++++++++++++++++++++++++++++++++++++--
 2 files changed, 38 insertions(+), 2 deletions(-)

diff --git a/include/linux/console.h b/include/linux/console.h
index 07005db4c788..8ce29b2381d2 100644
--- a/include/linux/console.h
+++ b/include/linux/console.h
@@ -189,6 +189,8 @@ extern void resume_console(void);
 
 extern void printk_emergency_begin(void);
 extern void printk_emergency_end(void);
+extern int printk_emergency_begin_sync(void);
+extern int printk_emergency_end_sync(void);
 
 int mda_console_init(void);
 void prom_con_init(void);
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index a86767d4d619..5d4b4beeebf5 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -485,8 +485,8 @@ static inline bool printk_kthread_should_stop(void)
 {
 	if (current != printk_kthread)
 		return false;
-	/* An emergency mode */
-	return (atomic_read(&printk_emergency) != 0);
+	/* An emergency mode or a pending printk_emergency_begin_sync() */
+	return (atomic_read(&printk_emergency) != 0 || kthread_should_park());
 }
 
 /*
@@ -509,6 +509,34 @@ void printk_emergency_end(void)
 }
 EXPORT_SYMBOL_GPL(printk_emergency_end);
 
+/*
+ * This disables printing offloading and instead attempts
+ * to do the usual console_trylock()->console_unlock().
+ *
+ * Note, this does wait for printk_kthread to stop.
+ */
+int printk_emergency_begin_sync(void)
+{
+	atomic_inc(&printk_emergency);
+	if (!printk_kthread)
+		return -EINVAL;
+
+	return kthread_park(printk_kthread);
+}
+EXPORT_SYMBOL_GPL(printk_emergency_begin_sync);
+
+/* This re-enables printk_kthread offloading. */
+int printk_emergency_end_sync(void)
+{
+	atomic_dec(&printk_emergency);
+	if (!printk_kthread)
+		return -EINVAL;
+
+	kthread_unpark(printk_kthread);
+	return 0;
+}
+EXPORT_SYMBOL_GPL(printk_emergency_end_sync);
+
 /*
  * Under heavy printing load or with a slow serial console (or both)
  * console_unlock() can stall CPUs, which can result in soft/hard-lockups,
@@ -2018,6 +2046,12 @@ EXPORT_SYMBOL_GPL(printk_emergency_begin);
 void printk_emergency_end(void) {}
 EXPORT_SYMBOL_GPL(printk_emergency_end);
 
+int printk_emergency_begin_sync(void) {}
+EXPORT_SYMBOL_GPL(printk_emergency_begin_sync);
+
+int printk_emergency_end_sync(void) {}
+EXPORT_SYMBOL_GPL(printk_emergency_end_sync);
+
 static inline bool console_offload_printing(void) { return false; }
 
 #endif /* CONFIG_PRINTK */
-- 
2.14.1

^ permalink raw reply	[flat|nested] 94+ messages in thread

* [RFC][PATCHv5 04/13] printk: add enforce_emergency parameter
  2017-08-15  2:56 [RFC][PATCHv5 00/13] printk: introduce printing kernel thread Sergey Senozhatsky
                   ` (2 preceding siblings ...)
  2017-08-15  2:56 ` [RFC][PATCHv5 03/13] printk: add sync printk_emergency API Sergey Senozhatsky
@ 2017-08-15  2:56 ` Sergey Senozhatsky
  2017-08-15  2:56 ` [RFC][PATCHv5 05/13] printk: enable printk offloading Sergey Senozhatsky
                   ` (10 subsequent siblings)
  14 siblings, 0 replies; 94+ messages in thread
From: Sergey Senozhatsky @ 2017-08-15  2:56 UTC (permalink / raw)
  To: Petr Mladek, Steven Rostedt
  Cc: Jan Kara, Andrew Morton, Peter Zijlstra, Rafael J . Wysocki,
	Eric Biederman, Greg Kroah-Hartman, Jiri Slaby, Pavel Machek,
	Andreas Mohr, Tetsuo Handa, linux-kernel, Sergey Senozhatsky,
	Sergey Senozhatsky

This param permits user-space to forcibly on/off printk emergency
mode via `/sys/module/printk/parameters/enforce_emergency' node.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 Documentation/admin-guide/kernel-parameters.txt | 7 +++++++
 kernel/printk/printk.c                          | 8 +++++++-
 2 files changed, 14 insertions(+), 1 deletion(-)

diff --git a/Documentation/admin-guide/kernel-parameters.txt b/Documentation/admin-guide/kernel-parameters.txt
index b5b6d5d24596..001f578ec5f5 100644
--- a/Documentation/admin-guide/kernel-parameters.txt
+++ b/Documentation/admin-guide/kernel-parameters.txt
@@ -3215,6 +3215,13 @@
 
 			default: off.
 
+	printk.enforce_emergency=
+			This parameter allows to disable/enable printing
+			offloading to printk kthread.
+			Format: <bool> (1 - emergency, 0 - permit offloading).
+
+			default: off.
+
 	processor.max_cstate=	[HW,ACPI]
 			Limit processor to maximum C-state
 			max_cstate=9 overrides any DMI blacklist limit.
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 5d4b4beeebf5..3a0e78812818 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -455,9 +455,15 @@ static cpumask_var_t printk_offload_cpus;
 static atomic_t printk_emergency __read_mostly;
 /*
  * Disable printk_kthread permanently. Unlike `oops_in_progress'
- * it doesn't go back to 0.
+ * it doesn't go back to 0 (unless set by user-space).
  */
 static bool printk_enforce_emergency __read_mostly;
+
+module_param_named(enforce_emergency, printk_enforce_emergency,
+		    bool, 0644);
+MODULE_PARM_DESC(printk_enforce_emergency,
+		 "don't offload message printing to printk kthread");
+
 /*
  * The number of seconds a task can print before it offloads printing
  * duty to printk_kthread. 0 indicates 'no limit'.
-- 
2.14.1

^ permalink raw reply	[flat|nested] 94+ messages in thread

* [RFC][PATCHv5 05/13] printk: enable printk offloading
  2017-08-15  2:56 [RFC][PATCHv5 00/13] printk: introduce printing kernel thread Sergey Senozhatsky
                   ` (3 preceding siblings ...)
  2017-08-15  2:56 ` [RFC][PATCHv5 04/13] printk: add enforce_emergency parameter Sergey Senozhatsky
@ 2017-08-15  2:56 ` Sergey Senozhatsky
  2017-08-15  2:56 ` [RFC][PATCHv5 06/13] printk: register PM notifier Sergey Senozhatsky
                   ` (9 subsequent siblings)
  14 siblings, 0 replies; 94+ messages in thread
From: Sergey Senozhatsky @ 2017-08-15  2:56 UTC (permalink / raw)
  To: Petr Mladek, Steven Rostedt
  Cc: Jan Kara, Andrew Morton, Peter Zijlstra, Rafael J . Wysocki,
	Eric Biederman, Greg Kroah-Hartman, Jiri Slaby, Pavel Machek,
	Andreas Mohr, Tetsuo Handa, linux-kernel, Sergey Senozhatsky,
	Sergey Senozhatsky

Initialize kernel printing thread and make printk offloading
possible. By default `atomic_print_limit' is set to 0, so no
offloading will take place, unless requested by user.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 kernel/printk/printk.c | 59 ++++++++++++++++++++++++++++++++++++++++++++++++++
 1 file changed, 59 insertions(+)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 3a0e78812818..05165f008bc8 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2913,6 +2913,65 @@ static DEFINE_PER_CPU(struct irq_work, wake_up_klogd_work) = {
 	.flags = IRQ_WORK_LAZY,
 };
 
+static int printk_kthread_func(void *data)
+{
+	while (1) {
+		set_current_state(TASK_INTERRUPTIBLE);
+		/*
+		 * We must check `printk_emergency' as well, to let
+		 * printk_emergency_begin() stop active `printk_kthread' at
+		 * some point. Otherwise we can end up in a loop:
+		 *   - we bail out of console_unlock() because of
+		 *     printk_kthread_should_stop()
+		 * and
+		 *   - don't schedule() and attempt to return back
+		 *     immediately to console_unlock() because we
+		 *     see PRINTK_PENDING_OUTPUT bit set.
+		 */
+		if (!test_bit(PRINTK_PENDING_OUTPUT, &printk_pending) ||
+				atomic_read(&printk_emergency) != 0)
+			schedule();
+
+		__set_current_state(TASK_RUNNING);
+
+		/* We might have been woken for stop */
+		if (kthread_should_park())
+			kthread_parkme();
+
+		console_lock();
+		console_unlock();
+
+		/* We might have been blocked on console_sem */
+		if (kthread_should_park())
+			kthread_parkme();
+	}
+
+	return 0;
+}
+
+/*
+ * Init printk kthread at late_initcall stage, after core/arch/device/etc.
+ * initialization.
+ */
+static int __init init_printk_kthread(void)
+{
+	struct task_struct *thread;
+
+	if (!alloc_cpumask_var(&printk_offload_cpus, GFP_KERNEL))
+		return -ENOMEM;
+
+	thread = kthread_run(printk_kthread_func, NULL, "printk");
+	if (IS_ERR(thread)) {
+		pr_err("printk: unable to create printing thread\n");
+		free_cpumask_var(printk_offload_cpus);
+		return PTR_ERR(thread);
+	}
+
+	printk_kthread = thread;
+	return 0;
+}
+late_initcall(init_printk_kthread);
+
 void wake_up_klogd(void)
 {
 	preempt_disable();
-- 
2.14.1

^ permalink raw reply	[flat|nested] 94+ messages in thread

* [RFC][PATCHv5 06/13] printk: register PM notifier
  2017-08-15  2:56 [RFC][PATCHv5 00/13] printk: introduce printing kernel thread Sergey Senozhatsky
                   ` (4 preceding siblings ...)
  2017-08-15  2:56 ` [RFC][PATCHv5 05/13] printk: enable printk offloading Sergey Senozhatsky
@ 2017-08-15  2:56 ` Sergey Senozhatsky
  2017-08-15 11:51   ` Rafael J. Wysocki
  2017-08-15  2:56 ` [RFC][PATCHv5 07/13] printk: register syscore notifier Sergey Senozhatsky
                   ` (8 subsequent siblings)
  14 siblings, 1 reply; 94+ messages in thread
From: Sergey Senozhatsky @ 2017-08-15  2:56 UTC (permalink / raw)
  To: Petr Mladek, Steven Rostedt
  Cc: Jan Kara, Andrew Morton, Peter Zijlstra, Rafael J . Wysocki,
	Eric Biederman, Greg Kroah-Hartman, Jiri Slaby, Pavel Machek,
	Andreas Mohr, Tetsuo Handa, linux-kernel, Sergey Senozhatsky,
	Sergey Senozhatsky

It's not always possible/safe to wake_up() printk kernel
thread. For example, late suspend/early resume may printk()
while timekeeping is not initialized yet, so calling into the
scheduler may result in recursive warnings.

Another thing to notice is the fact that PM at some point
freezes user space and kernel threads: freeze_processes()
and freeze_kernel_threads(), correspondingly. Thus we need
printk() to operate in emergency mode there and attempt to
immediately flush pending kernel message to the console.

This patch registers PM notifier, so PM can switch printk
to emergency mode from PM_FOO_PREPARE notifiers and return
back to printk threaded mode from PM_POST_FOO notifiers.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
Suggested-by: Andreas Mohr <andi@lisas.de>
---
 kernel/printk/printk.c | 35 +++++++++++++++++++++++++++++++++++
 1 file changed, 35 insertions(+)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 05165f008bc8..d3f149fad85c 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -49,6 +49,7 @@
 #include <linux/sched/debug.h>
 #include <linux/sched/task_stack.h>
 #include <linux/kthread.h>
+#include <linux/suspend.h>
 
 #include <linux/uaccess.h>
 #include <asm/sections.h>
@@ -2913,6 +2914,33 @@ static DEFINE_PER_CPU(struct irq_work, wake_up_klogd_work) = {
 	.flags = IRQ_WORK_LAZY,
 };
 
+static int printk_pm_notify(struct notifier_block *notify_block,
+			    unsigned long mode, void *unused)
+{
+	switch (mode) {
+	case PM_HIBERNATION_PREPARE:
+	case PM_SUSPEND_PREPARE:
+	case PM_RESTORE_PREPARE:
+		printk_emergency_begin_sync();
+		break;
+
+	case PM_POST_SUSPEND:
+	case PM_POST_HIBERNATION:
+	case PM_POST_RESTORE:
+		printk_emergency_end_sync();
+		break;
+
+	default:
+		return NOTIFY_DONE;
+	}
+
+	return NOTIFY_OK;
+}
+
+static struct notifier_block printk_pm_nb = {
+	.notifier_call = printk_pm_notify,
+};
+
 static int printk_kthread_func(void *data)
 {
 	while (1) {
@@ -2960,9 +2988,16 @@ static int __init init_printk_kthread(void)
 	if (!alloc_cpumask_var(&printk_offload_cpus, GFP_KERNEL))
 		return -ENOMEM;
 
+	if (register_pm_notifier(&printk_pm_nb) != 0) {
+		pr_err("printk: unable to register PM notifier\n");
+		free_cpumask_var(printk_offload_cpus);
+		return -EINVAL;
+	}
+
 	thread = kthread_run(printk_kthread_func, NULL, "printk");
 	if (IS_ERR(thread)) {
 		pr_err("printk: unable to create printing thread\n");
+		unregister_pm_notifier(&printk_pm_nb);
 		free_cpumask_var(printk_offload_cpus);
 		return PTR_ERR(thread);
 	}
-- 
2.14.1

^ permalink raw reply	[flat|nested] 94+ messages in thread

* [RFC][PATCHv5 07/13] printk: register syscore notifier
  2017-08-15  2:56 [RFC][PATCHv5 00/13] printk: introduce printing kernel thread Sergey Senozhatsky
                   ` (5 preceding siblings ...)
  2017-08-15  2:56 ` [RFC][PATCHv5 06/13] printk: register PM notifier Sergey Senozhatsky
@ 2017-08-15  2:56 ` Sergey Senozhatsky
  2017-08-15 11:56   ` Rafael J. Wysocki
  2017-08-15  2:56 ` [RFC][PATCHv5 08/13] printk: set watchdog_thresh as maximum value for atomic_print_limit Sergey Senozhatsky
                   ` (7 subsequent siblings)
  14 siblings, 1 reply; 94+ messages in thread
From: Sergey Senozhatsky @ 2017-08-15  2:56 UTC (permalink / raw)
  To: Petr Mladek, Steven Rostedt
  Cc: Jan Kara, Andrew Morton, Peter Zijlstra, Rafael J . Wysocki,
	Eric Biederman, Greg Kroah-Hartman, Jiri Slaby, Pavel Machek,
	Andreas Mohr, Tetsuo Handa, linux-kernel, Sergey Senozhatsky,
	Sergey Senozhatsky

We need to switch to emergency printk mode in kernel_kexec(). One
kernel_kexec() branch calls kernel_restart_prepare(), which updates
`system_state', however, the other one, when user requested to
->preserve_context, does not and we are lacking the information
in printk about kexec being executed. Register a syscore notifier
so printk will be notified by syscore_suspend().

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 kernel/printk/printk.c | 19 +++++++++++++++++++
 1 file changed, 19 insertions(+)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index d3f149fad85c..b14e35f94596 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -50,6 +50,7 @@
 #include <linux/sched/task_stack.h>
 #include <linux/kthread.h>
 #include <linux/suspend.h>
+#include <linux/syscore_ops.h>
 
 #include <linux/uaccess.h>
 #include <asm/sections.h>
@@ -2941,6 +2942,22 @@ static struct notifier_block printk_pm_nb = {
 	.notifier_call = printk_pm_notify,
 };
 
+static int printk_syscore_suspend(void)
+{
+	printk_emergency_begin();
+	return 0;
+}
+
+static void printk_syscore_resume(void)
+{
+	printk_emergency_end();
+}
+
+static struct syscore_ops printk_syscore_ops = {
+	.suspend = printk_syscore_suspend,
+	.resume = printk_syscore_resume,
+};
+
 static int printk_kthread_func(void *data)
 {
 	while (1) {
@@ -2994,6 +3011,8 @@ static int __init init_printk_kthread(void)
 		return -EINVAL;
 	}
 
+	register_syscore_ops(&printk_syscore_ops);
+
 	thread = kthread_run(printk_kthread_func, NULL, "printk");
 	if (IS_ERR(thread)) {
 		pr_err("printk: unable to create printing thread\n");
-- 
2.14.1

^ permalink raw reply	[flat|nested] 94+ messages in thread

* [RFC][PATCHv5 08/13] printk: set watchdog_thresh as maximum value for atomic_print_limit
  2017-08-15  2:56 [RFC][PATCHv5 00/13] printk: introduce printing kernel thread Sergey Senozhatsky
                   ` (6 preceding siblings ...)
  2017-08-15  2:56 ` [RFC][PATCHv5 07/13] printk: register syscore notifier Sergey Senozhatsky
@ 2017-08-15  2:56 ` Sergey Senozhatsky
  2017-08-15  2:56 ` [RFC][PATCHv5 09/13] printk: add auto-emergency enforcement mechanism Sergey Senozhatsky
                   ` (6 subsequent siblings)
  14 siblings, 0 replies; 94+ messages in thread
From: Sergey Senozhatsky @ 2017-08-15  2:56 UTC (permalink / raw)
  To: Petr Mladek, Steven Rostedt
  Cc: Jan Kara, Andrew Morton, Peter Zijlstra, Rafael J . Wysocki,
	Eric Biederman, Greg Kroah-Hartman, Jiri Slaby, Pavel Machek,
	Andreas Mohr, Tetsuo Handa, linux-kernel, Sergey Senozhatsky,
	Sergey Senozhatsky

There is no point in setting `atomic_print_limit' significantly
larger than watchdog's lockup threshold. This highly increases
the chances of lockups. Watchdog's softlockup threshold is
`2 * watchdog_thresh', but we limit `atomic_print_limit' to just
`watchdog_thresh'.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 kernel/printk/printk.c | 15 +++++++++++++++
 1 file changed, 15 insertions(+)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index b14e35f94596..12284aa30025 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -545,6 +545,19 @@ int printk_emergency_end_sync(void)
 }
 EXPORT_SYMBOL_GPL(printk_emergency_end_sync);
 
+/*
+ * We offload to make watchdog lockup detector happy, there is little
+ * point (no point at all) in setting `atomic_print_limit' larger than
+ * `watchdog_thresh'.
+ */
+static inline void adj_atomic_print_limit(void)
+{
+#ifdef CONFIG_LOCKUP_DETECTOR
+	if (watchdog_thresh && atomic_print_limit > watchdog_thresh)
+		atomic_print_limit = watchdog_thresh;
+#endif
+}
+
 /*
  * Under heavy printing load or with a slow serial console (or both)
  * console_unlock() can stall CPUs, which can result in soft/hard-lockups,
@@ -580,6 +593,8 @@ static inline bool console_offload_printing(void)
 	if (current == printk_kthread)
 		return false;
 
+	adj_atomic_print_limit();
+
 	if (!time_after_eq(now, printing_start_ts + atomic_print_limit))
 		return false;
 
-- 
2.14.1

^ permalink raw reply	[flat|nested] 94+ messages in thread

* [RFC][PATCHv5 09/13] printk: add auto-emergency enforcement mechanism
  2017-08-15  2:56 [RFC][PATCHv5 00/13] printk: introduce printing kernel thread Sergey Senozhatsky
                   ` (7 preceding siblings ...)
  2017-08-15  2:56 ` [RFC][PATCHv5 08/13] printk: set watchdog_thresh as maximum value for atomic_print_limit Sergey Senozhatsky
@ 2017-08-15  2:56 ` Sergey Senozhatsky
  2017-08-15  2:56 ` [RFC][PATCHv5 10/13] printk: force printk_kthread to offload printing Sergey Senozhatsky
                   ` (5 subsequent siblings)
  14 siblings, 0 replies; 94+ messages in thread
From: Sergey Senozhatsky @ 2017-08-15  2:56 UTC (permalink / raw)
  To: Petr Mladek, Steven Rostedt
  Cc: Jan Kara, Andrew Morton, Peter Zijlstra, Rafael J . Wysocki,
	Eric Biederman, Greg Kroah-Hartman, Jiri Slaby, Pavel Machek,
	Andreas Mohr, Tetsuo Handa, linux-kernel, Sergey Senozhatsky,
	Sergey Senozhatsky

Do not blindly offload printing, but check if offloading has
been successful. If we can't offload from this CPU for some
time, then we declare printk emergency and switch to old
printk behaviour (print all the pending messages with out
any offloading).

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 kernel/printk/printk.c | 22 ++++++++++++++++++++++
 1 file changed, 22 insertions(+)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 12284aa30025..71950bd85eac 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -558,6 +558,15 @@ static inline void adj_atomic_print_limit(void)
 #endif
 }
 
+static inline unsigned long emergency_timeout(unsigned long ts)
+{
+#ifdef CONFIG_LOCKUP_DETECTOR
+	if (watchdog_thresh)
+		return ts + 2 * watchdog_thresh;
+#endif
+	return ts + 10 * atomic_print_limit;
+}
+
 /*
  * Under heavy printing load or with a slow serial console (or both)
  * console_unlock() can stall CPUs, which can result in soft/hard-lockups,
@@ -571,6 +580,7 @@ static inline bool console_offload_printing(void)
 {
 	static struct task_struct *printing_task;
 	static unsigned long printing_start_ts;
+	static unsigned long saved_csw;
 	unsigned long now = local_clock() >> 30LL; /* seconds */
 
 	if (printk_kthread_should_stop())
@@ -585,6 +595,7 @@ static inline bool console_offload_printing(void)
 	/* A new task - reset the counters. */
 	if (printing_task != current) {
 		printing_start_ts = local_clock() >> 30LL;
+		saved_csw = current->nvcsw + current->nivcsw;
 		printing_task = current;
 		return false;
 	}
@@ -598,6 +609,17 @@ static inline bool console_offload_printing(void)
 	if (!time_after_eq(now, printing_start_ts + atomic_print_limit))
 		return false;
 
+	/*
+	 * A trivial emergency enforcement - give up on printk_kthread if
+	 * we can't wake it up.
+	 */
+	if (time_after_eq(now, emergency_timeout(printing_start_ts)) &&
+			saved_csw == (current->nvcsw + current->nivcsw)) {
+		printk_enforce_emergency = true;
+		pr_crit("Declaring printk emergency mode.\n");
+		return true;
+	}
+
 	/*
 	 * We try to set `printk_kthread' CPU affinity to any online CPU
 	 * except for this_cpu. Because otherwise `printk_kthread' may be
-- 
2.14.1

^ permalink raw reply	[flat|nested] 94+ messages in thread

* [RFC][PATCHv5 10/13] printk: force printk_kthread to offload printing
  2017-08-15  2:56 [RFC][PATCHv5 00/13] printk: introduce printing kernel thread Sergey Senozhatsky
                   ` (8 preceding siblings ...)
  2017-08-15  2:56 ` [RFC][PATCHv5 09/13] printk: add auto-emergency enforcement mechanism Sergey Senozhatsky
@ 2017-08-15  2:56 ` Sergey Senozhatsky
  2017-08-15  2:56 ` [RFC][PATCHv5 11/13] printk: always offload printing from user-space processes Sergey Senozhatsky
                   ` (4 subsequent siblings)
  14 siblings, 0 replies; 94+ messages in thread
From: Sergey Senozhatsky @ 2017-08-15  2:56 UTC (permalink / raw)
  To: Petr Mladek, Steven Rostedt
  Cc: Jan Kara, Andrew Morton, Peter Zijlstra, Rafael J . Wysocki,
	Eric Biederman, Greg Kroah-Hartman, Jiri Slaby, Pavel Machek,
	Andreas Mohr, Tetsuo Handa, linux-kernel, Sergey Senozhatsky,
	Sergey Senozhatsky

As of now we don't `offload' printing from printk_kthread and
print all pending logbuf messages. This, however, may have a
negative effect. We still hold console_sem as long as we have
got messages to print, and there might be other console_lock()
callers sleeping on console_sem in TASK_UNINTERRUPTIBLE,
including user space processes (tty_open, drm IOCTL, etc.).
So we need to up() console_sem every once in a while, even if
current console_sem owner is printk_kthread, just in order to
wake up those other processes that can sleep on console_sem.

If there are no tasks skeeping on console_sem, then printk_kthread
will immediately return back to console_unclok(), because we don't
clear the PRINTK_PENDING_OUTPUT bit and printk_kthread checks it
before it decides to schedule().

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 kernel/printk/printk.c | 22 ++++++++++++++++++----
 1 file changed, 18 insertions(+), 4 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 71950bd85eac..6da4e21c3b45 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -600,15 +600,29 @@ static inline bool console_offload_printing(void)
 		return false;
 	}
 
-	/* Once we offloaded to printk_ktread - keep printing */
-	if (current == printk_kthread)
-		return false;
-
 	adj_atomic_print_limit();
 
 	if (!time_after_eq(now, printing_start_ts + atomic_print_limit))
 		return false;
 
+	if (current == printk_kthread) {
+		/*
+		 * All tasks are equal, all tasks must offload. However,
+		 * printk_kthread may be the only process left willing to
+		 * down(). So we may return here immediately after we leave,
+		 * because of positive PRINTK_PENDING_OUTPUT check in
+		 * printk_kthread_func() loop. However, we obviously don't
+		 * want to declare printk emergency in this case, so that's
+		 * why we update `printing_start_ts' here.
+		 *
+		 * In case if `printk_kthread' will immediately return
+		 * back to console_unlock(), it will have another full
+		 * `atomic_print_limit' time slice.
+		 */
+		printing_start_ts = local_clock() >> 30LL;
+		return true;
+	}
+
 	/*
 	 * A trivial emergency enforcement - give up on printk_kthread if
 	 * we can't wake it up.
-- 
2.14.1

^ permalink raw reply	[flat|nested] 94+ messages in thread

* [RFC][PATCHv5 11/13] printk: always offload printing from user-space processes
  2017-08-15  2:56 [RFC][PATCHv5 00/13] printk: introduce printing kernel thread Sergey Senozhatsky
                   ` (9 preceding siblings ...)
  2017-08-15  2:56 ` [RFC][PATCHv5 10/13] printk: force printk_kthread to offload printing Sergey Senozhatsky
@ 2017-08-15  2:56 ` Sergey Senozhatsky
  2017-08-15  2:56 ` [RFC][PATCHv5 12/13] printk: do not cond_resched() when we can offload Sergey Senozhatsky
                   ` (3 subsequent siblings)
  14 siblings, 0 replies; 94+ messages in thread
From: Sergey Senozhatsky @ 2017-08-15  2:56 UTC (permalink / raw)
  To: Petr Mladek, Steven Rostedt
  Cc: Jan Kara, Andrew Morton, Peter Zijlstra, Rafael J . Wysocki,
	Eric Biederman, Greg Kroah-Hartman, Jiri Slaby, Pavel Machek,
	Andreas Mohr, Tetsuo Handa, linux-kernel, Sergey Senozhatsky,
	Sergey Senozhatsky

console_lock() and, thus, console_unlock() can be executed by
user-space processes doing sys calls (e.g. tty, drm, etc.) so we
may end up in a situation when systemd loops in console_unlock()
printing kernel messages. Always offload printing duty from
user-space process (if we can safely wake up printk_kthread,
of course).

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 kernel/printk/printk.c | 8 ++++++++
 1 file changed, 8 insertions(+)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 6da4e21c3b45..0ffbaa33280f 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -592,6 +592,13 @@ static inline bool console_offload_printing(void)
 	if (!is_printk_offloading_safe())
 		return false;
 
+	/*
+	 * Always offload from user-space processes, we've got printk kthread
+	 * for printing.
+	 */
+	if (!(current->flags & PF_KTHREAD))
+		goto offload;
+
 	/* A new task - reset the counters. */
 	if (printing_task != current) {
 		printing_start_ts = local_clock() >> 30LL;
@@ -634,6 +641,7 @@ static inline bool console_offload_printing(void)
 		return true;
 	}
 
+offload:
 	/*
 	 * We try to set `printk_kthread' CPU affinity to any online CPU
 	 * except for this_cpu. Because otherwise `printk_kthread' may be
-- 
2.14.1

^ permalink raw reply	[flat|nested] 94+ messages in thread

* [RFC][PATCHv5 12/13] printk: do not cond_resched() when we can offload
  2017-08-15  2:56 [RFC][PATCHv5 00/13] printk: introduce printing kernel thread Sergey Senozhatsky
                   ` (10 preceding siblings ...)
  2017-08-15  2:56 ` [RFC][PATCHv5 11/13] printk: always offload printing from user-space processes Sergey Senozhatsky
@ 2017-08-15  2:56 ` Sergey Senozhatsky
  2017-08-15  2:56 ` [RFC][PATCHv5 13/13] printk: move offloading logic to per-cpu Sergey Senozhatsky
                   ` (2 subsequent siblings)
  14 siblings, 0 replies; 94+ messages in thread
From: Sergey Senozhatsky @ 2017-08-15  2:56 UTC (permalink / raw)
  To: Petr Mladek, Steven Rostedt
  Cc: Jan Kara, Andrew Morton, Peter Zijlstra, Rafael J . Wysocki,
	Eric Biederman, Greg Kroah-Hartman, Jiri Slaby, Pavel Machek,
	Andreas Mohr, Tetsuo Handa, linux-kernel, Sergey Senozhatsky,
	Sergey Senozhatsky

console_unlock() may sleep with console_sem locked, which is a bit
counter intuitive: we neither print pending logbuf messages to the
serial console, nor let anyone else to do it for us.

With printing offloading enabled, however, we can disable preemption,
because we know for sure how long we can stay in console_unlock() and
that eventually we will offload to another task.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 kernel/printk/printk.c | 15 ++++++++++++++-
 1 file changed, 14 insertions(+), 1 deletion(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 0ffbaa33280f..ba82152ce5d9 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2432,6 +2432,14 @@ void console_unlock(void)
 	 * and cleared after the the "again" goto label.
 	 */
 	do_cond_resched = console_may_schedule;
+	/*
+	 * Forbid scheduling under the console_sem lock when offloading
+	 * is enabled. Scheduling will just slow down the print out in
+	 * this case.
+	 */
+	if (printk_offloading_enabled() && is_printk_offloading_safe())
+		do_cond_resched = 0;
+
 again:
 	console_may_schedule = 0;
 
@@ -2447,6 +2455,7 @@ void console_unlock(void)
 		return;
 	}
 
+	preempt_disable();
 	for (;;) {
 		struct printk_log *msg;
 		size_t ext_len = 0;
@@ -2507,8 +2516,11 @@ void console_unlock(void)
 		start_critical_timings();
 		printk_safe_exit_irqrestore(flags);
 
-		if (do_cond_resched)
+		if (do_cond_resched) {
+			preempt_enable();
 			cond_resched();
+			preempt_disable();
+		}
 	}
 	console_locked = 0;
 
@@ -2518,6 +2530,7 @@ void console_unlock(void)
 
 	raw_spin_unlock(&logbuf_lock);
 
+	preempt_enable();
 	up_console_sem();
 
 	/*
-- 
2.14.1

^ permalink raw reply	[flat|nested] 94+ messages in thread

* [RFC][PATCHv5 13/13] printk: move offloading logic to per-cpu
  2017-08-15  2:56 [RFC][PATCHv5 00/13] printk: introduce printing kernel thread Sergey Senozhatsky
                   ` (11 preceding siblings ...)
  2017-08-15  2:56 ` [RFC][PATCHv5 12/13] printk: do not cond_resched() when we can offload Sergey Senozhatsky
@ 2017-08-15  2:56 ` Sergey Senozhatsky
  2017-08-23  8:33 ` [RFC][PATCHv5 00/13] printk: introduce printing kernel thread Sergey Senozhatsky
  2017-08-28  9:05 ` printk: what is going on with additional newlines? Pavel Machek
  14 siblings, 0 replies; 94+ messages in thread
From: Sergey Senozhatsky @ 2017-08-15  2:56 UTC (permalink / raw)
  To: Petr Mladek, Steven Rostedt
  Cc: Jan Kara, Andrew Morton, Peter Zijlstra, Rafael J . Wysocki,
	Eric Biederman, Greg Kroah-Hartman, Jiri Slaby, Pavel Machek,
	Andreas Mohr, Tetsuo Handa, linux-kernel, Sergey Senozhatsky,
	Sergey Senozhatsky

We have a global offloading state and make the offloading
decision based on printing task pointer and timestamp. If
we keep seeing the same task performing printing for too
long (`atomic_print_limit') we request offloading. Similarly
when we see that printing is now performed by another task,
we reset the timestamp counter.

This, however, will not work in the following case:

===============================================================================

CPU0						CPU1
//taskA						//taskB
preempt_disable()				preempt_disable()

 printk()
  console_trylock()
  console_unlock()
   printing_task = taskA
  up()
						printk()
						 console_trylock()
						 console_unlock()
						  printing_task = taskB
						  ^^^ reset offloading control
						up()
 printk()
  console_trylock()
  console_unlock()
   printing_task = taskA
   ^^^ reset offloading control
  up()
						printk()
						 console_trylock()
						 console_unlock()
						  printing_task = taskB
						  ^^^ reset offloading control
						up()

/*
 * X seconds later
 */

 printk()
  console_trylock()
  console_unlock()
   printing_task = taskA
   ^^^ reset offloading control
  up()
						printk()
						 console_trylock()
						 console_unlock()
						  printing_task = taskB
						  ^^^ reset offloading control
						up()

 lockup!					lockup!

===============================================================================

So this printk ping-pong confuses our offloading control logic.
Move it to per-CPU area and have a separate offloading control
on every CPU.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 kernel/printk/printk.c | 36 ++++++++++++++++++++----------------
 1 file changed, 20 insertions(+), 16 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index ba82152ce5d9..f9799616e9fc 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -558,13 +558,14 @@ static inline void adj_atomic_print_limit(void)
 #endif
 }
 
-static inline unsigned long emergency_timeout(unsigned long ts)
+static inline unsigned long emergency_timeout(unsigned long now,
+						unsigned long ts)
 {
 #ifdef CONFIG_LOCKUP_DETECTOR
 	if (watchdog_thresh)
-		return ts + 2 * watchdog_thresh;
+		return time_after_eq(now, ts + 2 * watchdog_thresh);
 #endif
-	return ts + 10 * atomic_print_limit;
+	return time_after_eq(now, ts + 10 * atomic_print_limit);
 }
 
 /*
@@ -574,13 +575,13 @@ static inline unsigned long emergency_timeout(unsigned long ts)
  * amount of time a process can print from console_unlock().
  *
  * This function must be called from 'printk_safe' context under
- * console_sem lock.
+ * console_sem lock with preemption disabled.
  */
 static inline bool console_offload_printing(void)
 {
-	static struct task_struct *printing_task;
-	static unsigned long printing_start_ts;
-	static unsigned long saved_csw;
+	static DEFINE_PER_CPU(struct task_struct, *printing_task);
+	static DEFINE_PER_CPU(unsigned long, printing_start_ts);
+	static DEFINE_PER_CPU(unsigned long, saved_csw);
 	unsigned long now = local_clock() >> 30LL; /* seconds */
 
 	if (printk_kthread_should_stop())
@@ -600,16 +601,17 @@ static inline bool console_offload_printing(void)
 		goto offload;
 
 	/* A new task - reset the counters. */
-	if (printing_task != current) {
-		printing_start_ts = local_clock() >> 30LL;
-		saved_csw = current->nvcsw + current->nivcsw;
-		printing_task = current;
+	if (this_cpu_read(printing_task) != current) {
+		this_cpu_write(printing_start_ts, local_clock() >> 30LL);
+		this_cpu_write(saved_csw, current->nvcsw + current->nivcsw);
+		this_cpu_write(printing_task, current);
 		return false;
 	}
 
 	adj_atomic_print_limit();
 
-	if (!time_after_eq(now, printing_start_ts + atomic_print_limit))
+	if (!time_after_eq(now, this_cpu_read(printing_start_ts) +
+				atomic_print_limit))
 		return false;
 
 	if (current == printk_kthread) {
@@ -626,7 +628,7 @@ static inline bool console_offload_printing(void)
 		 * back to console_unlock(), it will have another full
 		 * `atomic_print_limit' time slice.
 		 */
-		printing_start_ts = local_clock() >> 30LL;
+		this_cpu_write(printing_start_ts, local_clock() >> 30LL);
 		return true;
 	}
 
@@ -634,10 +636,12 @@ static inline bool console_offload_printing(void)
 	 * A trivial emergency enforcement - give up on printk_kthread if
 	 * we can't wake it up.
 	 */
-	if (time_after_eq(now, emergency_timeout(printing_start_ts)) &&
-			saved_csw == (current->nvcsw + current->nivcsw)) {
+	if (this_cpu_read(saved_csw) == (current->nvcsw + current->nivcsw)
+		&& emergency_timeout(now, this_cpu_read(printing_start_ts))) {
+
 		printk_enforce_emergency = true;
-		pr_crit("Declaring printk emergency mode.\n");
+		pr_crit("CPU%d declared a printk emergency mode.\n",
+				smp_processor_id());
 		return true;
 	}
 
-- 
2.14.1

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: [RFC][PATCHv5 06/13] printk: register PM notifier
  2017-08-15  2:56 ` [RFC][PATCHv5 06/13] printk: register PM notifier Sergey Senozhatsky
@ 2017-08-15 11:51   ` Rafael J. Wysocki
  2017-08-16  7:31     ` Sergey Senozhatsky
  0 siblings, 1 reply; 94+ messages in thread
From: Rafael J. Wysocki @ 2017-08-15 11:51 UTC (permalink / raw)
  To: Sergey Senozhatsky
  Cc: Petr Mladek, Steven Rostedt, Jan Kara, Andrew Morton,
	Peter Zijlstra, Eric Biederman, Greg Kroah-Hartman, Jiri Slaby,
	Pavel Machek, Andreas Mohr, Tetsuo Handa, linux-kernel,
	Sergey Senozhatsky

On Tuesday, August 15, 2017 4:56:18 AM CEST Sergey Senozhatsky wrote:
> It's not always possible/safe to wake_up() printk kernel
> thread. For example, late suspend/early resume may printk()
> while timekeeping is not initialized yet, so calling into the
> scheduler may result in recursive warnings.
> 
> Another thing to notice is the fact that PM at some point
> freezes user space and kernel threads: freeze_processes()
> and freeze_kernel_threads(), correspondingly. Thus we need
> printk() to operate in emergency mode there and attempt to
> immediately flush pending kernel message to the console.
> 
> This patch registers PM notifier, so PM can switch printk
> to emergency mode from PM_FOO_PREPARE notifiers and return

Isn't that too early?  That's before user space is frozen even.

> back to printk threaded mode from PM_POST_FOO notifiers.

And isn't that too late?

> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> Suggested-by: Andreas Mohr <andi@lisas.de>
> ---
>  kernel/printk/printk.c | 35 +++++++++++++++++++++++++++++++++++
>  1 file changed, 35 insertions(+)
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 05165f008bc8..d3f149fad85c 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -49,6 +49,7 @@
>  #include <linux/sched/debug.h>
>  #include <linux/sched/task_stack.h>
>  #include <linux/kthread.h>
> +#include <linux/suspend.h>
>  
>  #include <linux/uaccess.h>
>  #include <asm/sections.h>
> @@ -2913,6 +2914,33 @@ static DEFINE_PER_CPU(struct irq_work, wake_up_klogd_work) = {
>  	.flags = IRQ_WORK_LAZY,
>  };
>  
> +static int printk_pm_notify(struct notifier_block *notify_block,
> +			    unsigned long mode, void *unused)
> +{
> +	switch (mode) {
> +	case PM_HIBERNATION_PREPARE:
> +	case PM_SUSPEND_PREPARE:
> +	case PM_RESTORE_PREPARE:
> +		printk_emergency_begin_sync();

I'm not sure what would be wrong with calling this directly
from dpm_suspend_noirq().

> +		break;
> +
> +	case PM_POST_SUSPEND:
> +	case PM_POST_HIBERNATION:
> +	case PM_POST_RESTORE:
> +		printk_emergency_end_sync();

And this could be called from dpm_resume_noirq().

In which case you wouldn't really need the stuff below.

Thanks,
Rafael

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: [RFC][PATCHv5 07/13] printk: register syscore notifier
  2017-08-15  2:56 ` [RFC][PATCHv5 07/13] printk: register syscore notifier Sergey Senozhatsky
@ 2017-08-15 11:56   ` Rafael J. Wysocki
  2017-08-16  6:55     ` Sergey Senozhatsky
  0 siblings, 1 reply; 94+ messages in thread
From: Rafael J. Wysocki @ 2017-08-15 11:56 UTC (permalink / raw)
  To: Sergey Senozhatsky
  Cc: Petr Mladek, Steven Rostedt, Jan Kara, Andrew Morton,
	Peter Zijlstra, Eric Biederman, Greg Kroah-Hartman, Jiri Slaby,
	Pavel Machek, Andreas Mohr, Tetsuo Handa, linux-kernel,
	Sergey Senozhatsky

On Tuesday, August 15, 2017 4:56:19 AM CEST Sergey Senozhatsky wrote:
> We need to switch to emergency printk mode in kernel_kexec(). One
> kernel_kexec() branch calls kernel_restart_prepare(), which updates
> `system_state', however, the other one, when user requested to
> ->preserve_context, does not and we are lacking the information
> in printk about kexec being executed. Register a syscore notifier
> so printk will be notified by syscore_suspend().
> 
> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> ---
>  kernel/printk/printk.c | 19 +++++++++++++++++++
>  1 file changed, 19 insertions(+)
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index d3f149fad85c..b14e35f94596 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -50,6 +50,7 @@
>  #include <linux/sched/task_stack.h>
>  #include <linux/kthread.h>
>  #include <linux/suspend.h>
> +#include <linux/syscore_ops.h>
>  
>  #include <linux/uaccess.h>
>  #include <asm/sections.h>
> @@ -2941,6 +2942,22 @@ static struct notifier_block printk_pm_nb = {
>  	.notifier_call = printk_pm_notify,
>  };
>  
> +static int printk_syscore_suspend(void)
> +{
> +	printk_emergency_begin();
> +	return 0;
> +}

Somebody looking at suspend/resume code paths only will be wondering why
you need this, because we should be in the emergency mode already when
it is called.

It would be good to add a comment about the kexec context here.

> +
> +static void printk_syscore_resume(void)
> +{
> +	printk_emergency_end();
> +}

This will turn the emergency mode off during resume before the notifier
added by the previous patch AFAICS.  Is this intentional?

Thanks,
Rafael

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: [RFC][PATCHv5 07/13] printk: register syscore notifier
  2017-08-15 11:56   ` Rafael J. Wysocki
@ 2017-08-16  6:55     ` Sergey Senozhatsky
  2017-08-16 12:59       ` Rafael J. Wysocki
  0 siblings, 1 reply; 94+ messages in thread
From: Sergey Senozhatsky @ 2017-08-16  6:55 UTC (permalink / raw)
  To: Rafael J. Wysocki
  Cc: Sergey Senozhatsky, Petr Mladek, Steven Rostedt, Jan Kara,
	Andrew Morton, Peter Zijlstra, Eric Biederman,
	Greg Kroah-Hartman, Jiri Slaby, Pavel Machek, Andreas Mohr,
	Tetsuo Handa, linux-kernel, Sergey Senozhatsky

On (08/15/17 13:56), Rafael J. Wysocki wrote:
[..]
> > +static int printk_syscore_suspend(void)
> > +{
> > +	printk_emergency_begin();
> > +	return 0;
> > +}
> 
> Somebody looking at suspend/resume code paths only will be wondering why
> you need this, because we should be in the emergency mode already when
> it is called.
> 
> It would be good to add a comment about the kexec context here.

ok, will add.

> > +static void printk_syscore_resume(void)
> > +{
> > +	printk_emergency_end();
> > +}
> 
> This will turn the emergency mode off during resume before the notifier
> added by the previous patch AFAICS.  Is this intentional?

emergency modes can nest. so it's OK to have

	printk_emergency_begin()   +1   // on
	  printk_emergency_begin()   +1
	  printk_emergency_end()     -1
	printk_emergency_end()     -1   // off

or did I misunderstand your question?

	-ss

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: [RFC][PATCHv5 06/13] printk: register PM notifier
  2017-08-15 11:51   ` Rafael J. Wysocki
@ 2017-08-16  7:31     ` Sergey Senozhatsky
  2017-08-16 12:58       ` Rafael J. Wysocki
  0 siblings, 1 reply; 94+ messages in thread
From: Sergey Senozhatsky @ 2017-08-16  7:31 UTC (permalink / raw)
  To: Rafael J. Wysocki
  Cc: Sergey Senozhatsky, Petr Mladek, Steven Rostedt, Jan Kara,
	Andrew Morton, Peter Zijlstra, Eric Biederman,
	Greg Kroah-Hartman, Jiri Slaby, Pavel Machek, Andreas Mohr,
	Tetsuo Handa, linux-kernel, Sergey Senozhatsky

On (08/15/17 13:51), Rafael J. Wysocki wrote:
> On Tuesday, August 15, 2017 4:56:18 AM CEST Sergey Senozhatsky wrote:
[..]
> > This patch registers PM notifier, so PM can switch printk
> > to emergency mode from PM_FOO_PREPARE notifiers and return
> 
> Isn't that too early?  That's before user space is frozen even.
> 
> > back to printk threaded mode from PM_POST_FOO notifiers.
> 
> And isn't that too late?

hm, those two are interesting questions. in short - well, it might
be. I don't want to interfere with PM by doing 'accidental' offloading
etc., PM is too complicated already. so I'd prefer to switch to old
printk behavior early (besides, I tend to see lockups reports more
often when the kernel is up and running, rather than during PM events.)
but, once again, may be it is too early and we can move emergency_mode
switch.

[..]
> > +static int printk_pm_notify(struct notifier_block *notify_block,
> > +			    unsigned long mode, void *unused)
> > +{
> > +	switch (mode) {
> > +	case PM_HIBERNATION_PREPARE:
> > +	case PM_SUSPEND_PREPARE:
> > +	case PM_RESTORE_PREPARE:
> > +		printk_emergency_begin_sync();
> 
> I'm not sure what would be wrong with calling this directly
> from dpm_suspend_noirq().
> 
> > +		break;
> > +
> > +	case PM_POST_SUSPEND:
> > +	case PM_POST_HIBERNATION:
> > +	case PM_POST_RESTORE:
> > +		printk_emergency_end_sync();
> 
> And this could be called from dpm_resume_noirq().
> 
> In which case you wouldn't really need the stuff below.

we didn't want to spread printk_emergency_{begin, end}
calls across the kernel.

as of dpm_suspend_noirq/dpm_resume_noirq - I need to look more.
isn't dpm_{suspend, resume}_noirq too late/early? :)

dpm_resume_noirq() happens much earlier than
suspend_finish()->suspend_thaw_processes(), right?
do we want to enable offloading this early?

currently what we have is the following sequence

suspend_finish()
  suspend_thaw_processes()
    pm_notifier_call_chain(PM_POST_SUSPEND)    // enable offloading
      pm_restore_console()

which looks OK to me, frankly.
do you see any problems here?

	-ss

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: [RFC][PATCHv5 06/13] printk: register PM notifier
  2017-08-16  7:31     ` Sergey Senozhatsky
@ 2017-08-16 12:58       ` Rafael J. Wysocki
  2017-08-17  5:55         ` Sergey Senozhatsky
  0 siblings, 1 reply; 94+ messages in thread
From: Rafael J. Wysocki @ 2017-08-16 12:58 UTC (permalink / raw)
  To: Sergey Senozhatsky
  Cc: Sergey Senozhatsky, Petr Mladek, Steven Rostedt, Jan Kara,
	Andrew Morton, Peter Zijlstra, Eric Biederman,
	Greg Kroah-Hartman, Jiri Slaby, Pavel Machek, Andreas Mohr,
	Tetsuo Handa, linux-kernel

On Wednesday, August 16, 2017 9:31:17 AM CEST Sergey Senozhatsky wrote:
> On (08/15/17 13:51), Rafael J. Wysocki wrote:
> > On Tuesday, August 15, 2017 4:56:18 AM CEST Sergey Senozhatsky wrote:
> [..]
> > > This patch registers PM notifier, so PM can switch printk
> > > to emergency mode from PM_FOO_PREPARE notifiers and return
> > 
> > Isn't that too early?  That's before user space is frozen even.
> > 
> > > back to printk threaded mode from PM_POST_FOO notifiers.
> > 
> > And isn't that too late?
> 
> hm, those two are interesting questions. in short - well, it might
> be. I don't want to interfere with PM by doing 'accidental' offloading
> etc., PM is too complicated already. so I'd prefer to switch to old
> printk behavior early (besides, I tend to see lockups reports more
> often when the kernel is up and running, rather than during PM events.)
> but, once again, may be it is too early and we can move emergency_mode
> switch.

Well, that depends on what your goal is really.

I thought you wanted to do the offloading as far into the suspend as it
was safe to do (and analogously for resume), but now I see you want to
stop doing it as early as it makes sense. :-)

In that case I would call printk_emergency_begin_sync() from
dpm_prepare() and printk_emergency_end_sync() from dpm_complete().

> 
> [..]
> > > +static int printk_pm_notify(struct notifier_block *notify_block,
> > > +			    unsigned long mode, void *unused)
> > > +{
> > > +	switch (mode) {
> > > +	case PM_HIBERNATION_PREPARE:
> > > +	case PM_SUSPEND_PREPARE:
> > > +	case PM_RESTORE_PREPARE:
> > > +		printk_emergency_begin_sync();
> > 
> > I'm not sure what would be wrong with calling this directly
> > from dpm_suspend_noirq().
> > 
> > > +		break;
> > > +
> > > +	case PM_POST_SUSPEND:
> > > +	case PM_POST_HIBERNATION:
> > > +	case PM_POST_RESTORE:
> > > +		printk_emergency_end_sync();
> > 
> > And this could be called from dpm_resume_noirq().
> > 
> > In which case you wouldn't really need the stuff below.
> 
> we didn't want to spread printk_emergency_{begin, end}
> calls across the kernel.

But this adds one invocation of each of them anyway *plus* some
extra code around those.  Wouldn't it be cleaner to add those
invocations alone?

> 
> as of dpm_suspend_noirq/dpm_resume_noirq - I need to look more.
> isn't dpm_{suspend, resume}_noirq too late/early? :)
> 
> dpm_resume_noirq() happens much earlier than
> suspend_finish()->suspend_thaw_processes(), right?
> do we want to enable offloading this early?
> 
> currently what we have is the following sequence
> 
> suspend_finish()
>   suspend_thaw_processes()
>     pm_notifier_call_chain(PM_POST_SUSPEND)    // enable offloading
>       pm_restore_console()
> 
> which looks OK to me, frankly.
> do you see any problems here?

I just don't see much point in using the notifier thing if you can
achieve basically the same without using it. :-)

Thanks,
Rafael

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: [RFC][PATCHv5 07/13] printk: register syscore notifier
  2017-08-16  6:55     ` Sergey Senozhatsky
@ 2017-08-16 12:59       ` Rafael J. Wysocki
  0 siblings, 0 replies; 94+ messages in thread
From: Rafael J. Wysocki @ 2017-08-16 12:59 UTC (permalink / raw)
  To: Sergey Senozhatsky
  Cc: Sergey Senozhatsky, Petr Mladek, Steven Rostedt, Jan Kara,
	Andrew Morton, Peter Zijlstra, Eric Biederman,
	Greg Kroah-Hartman, Jiri Slaby, Pavel Machek, Andreas Mohr,
	Tetsuo Handa, linux-kernel

On Wednesday, August 16, 2017 8:55:45 AM CEST Sergey Senozhatsky wrote:
> On (08/15/17 13:56), Rafael J. Wysocki wrote:
> [..]
> > > +static int printk_syscore_suspend(void)
> > > +{
> > > +	printk_emergency_begin();
> > > +	return 0;
> > > +}
> > 
> > Somebody looking at suspend/resume code paths only will be wondering why
> > you need this, because we should be in the emergency mode already when
> > it is called.
> > 
> > It would be good to add a comment about the kexec context here.
> 
> ok, will add.
> 
> > > +static void printk_syscore_resume(void)
> > > +{
> > > +	printk_emergency_end();
> > > +}
> > 
> > This will turn the emergency mode off during resume before the notifier
> > added by the previous patch AFAICS.  Is this intentional?
> 
> emergency modes can nest. so it's OK to have
> 
> 	printk_emergency_begin()   +1   // on
> 	  printk_emergency_begin()   +1
> 	  printk_emergency_end()     -1
> 	printk_emergency_end()     -1   // off
> 

OK then.

Thanks,
Rafel

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: [RFC][PATCHv5 06/13] printk: register PM notifier
  2017-08-16 12:58       ` Rafael J. Wysocki
@ 2017-08-17  5:55         ` Sergey Senozhatsky
  2017-08-17 15:43           ` Rafael J. Wysocki
  0 siblings, 1 reply; 94+ messages in thread
From: Sergey Senozhatsky @ 2017-08-17  5:55 UTC (permalink / raw)
  To: Rafael J. Wysocki
  Cc: Sergey Senozhatsky, Sergey Senozhatsky, Petr Mladek,
	Steven Rostedt, Jan Kara, Andrew Morton, Peter Zijlstra,
	Eric Biederman, Greg Kroah-Hartman, Jiri Slaby, Pavel Machek,
	Andreas Mohr, Tetsuo Handa, linux-kernel

Hello Rafael,

On (08/16/17 14:58), Rafael J. Wysocki wrote:
[..]
> > hm, those two are interesting questions. in short - well, it might
> > be. I don't want to interfere with PM by doing 'accidental' offloading
> > etc., PM is too complicated already. so I'd prefer to switch to old
> > printk behavior early (besides, I tend to see lockups reports more
> > often when the kernel is up and running, rather than during PM events.)
> > but, once again, may be it is too early and we can move emergency_mode
> > switch.
> 
> Well, that depends on what your goal is really.

to avoid any PM breakage :)

> I thought you wanted to do the offloading as far into the suspend as it
> was safe to do (and analogously for resume), but now I see you want to
> stop doing it as early as it makes sense. :-)

ideally yes :) but in reality I'd probably prefer to switch to emergency
printk ASAP during PM. we have reports of broken PM because of offloading
from Linaro (well... a long time ago, and printk kthread patch set was
completely different back then).

> In that case I would call printk_emergency_begin_sync() from
> dpm_prepare() and printk_emergency_end_sync() from dpm_complete().

hm, isn't it the case that dpm_prepare/dpm_complete are invoked only
by hibernate path? or does suspend path (s2ram, etc.) also calls
dpm_prepare/dpm_complete?

the 3 things we need to have (in PM context) for offloading:
- unparked printk kthread
- running scheduler
- online non-boot CPUs (on a UP system, or with non-boot CPUs disabled,
  offloading is a bit questionable)

- hm, may be something else...

[..]
> > we didn't want to spread printk_emergency_{begin, end}
> > calls across the kernel.
> 
> But this adds one invocation of each of them anyway *plus* some
> extra code around those.  Wouldn't it be cleaner to add those
> invocations alone?
[..]
> I just don't see much point in using the notifier thing if you can
> achieve basically the same without using it. :-)

sure, I just didn't want to mix printk internals with PM internals.
that would put us in position of verifying future PM changes from
printk-kthread point of view as well; and it can be quite complex,
because printk offloading brings in big guns like scheduler and
timekeeping. so the notifiers interface looks like a good
alternative, besides those notifications happen early (and late)
enough to keep us on the safe side.

well, I may be wrong.

	-ss

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: [RFC][PATCHv5 06/13] printk: register PM notifier
  2017-08-17  5:55         ` Sergey Senozhatsky
@ 2017-08-17 15:43           ` Rafael J. Wysocki
  2017-08-17 23:19             ` Sergey Senozhatsky
  0 siblings, 1 reply; 94+ messages in thread
From: Rafael J. Wysocki @ 2017-08-17 15:43 UTC (permalink / raw)
  To: Sergey Senozhatsky
  Cc: Sergey Senozhatsky, Petr Mladek, Steven Rostedt, Jan Kara,
	Andrew Morton, Peter Zijlstra, Eric Biederman,
	Greg Kroah-Hartman, Jiri Slaby, Pavel Machek, Andreas Mohr,
	Tetsuo Handa, linux-kernel

On Thursday, August 17, 2017 7:55:58 AM CEST Sergey Senozhatsky wrote:
> Hello Rafael,
> 
> On (08/16/17 14:58), Rafael J. Wysocki wrote:
> [..]
> > > hm, those two are interesting questions. in short - well, it might
> > > be. I don't want to interfere with PM by doing 'accidental' offloading
> > > etc., PM is too complicated already. so I'd prefer to switch to old
> > > printk behavior early (besides, I tend to see lockups reports more
> > > often when the kernel is up and running, rather than during PM events.)
> > > but, once again, may be it is too early and we can move emergency_mode
> > > switch.
> > 
> > Well, that depends on what your goal is really.
> 
> to avoid any PM breakage :)
> 
> > I thought you wanted to do the offloading as far into the suspend as it
> > was safe to do (and analogously for resume), but now I see you want to
> > stop doing it as early as it makes sense. :-)
> 
> ideally yes :) but in reality I'd probably prefer to switch to emergency
> printk ASAP during PM. we have reports of broken PM because of offloading
> from Linaro (well... a long time ago, and printk kthread patch set was
> completely different back then).
> 
> > In that case I would call printk_emergency_begin_sync() from
> > dpm_prepare() and printk_emergency_end_sync() from dpm_complete().
> 
> hm, isn't it the case that dpm_prepare/dpm_complete are invoked only
> by hibernate path? or does suspend path (s2ram, etc.) also calls
> dpm_prepare/dpm_complete?

Yes, it does.

> the 3 things we need to have (in PM context) for offloading:
> - unparked printk kthread
> - running scheduler
> - online non-boot CPUs (on a UP system, or with non-boot CPUs disabled,
>   offloading is a bit questionable)
> 
> - hm, may be something else...

All of that is there during the entire device suspend/resume including
dpm_suspend/resume_noirq().

But probably dpm_prepare/complete() are better places for the hooks at
least for now.

> 
> [..]
> > > we didn't want to spread printk_emergency_{begin, end}
> > > calls across the kernel.
> > 
> > But this adds one invocation of each of them anyway *plus* some
> > extra code around those.  Wouldn't it be cleaner to add those
> > invocations alone?
> [..]
> > I just don't see much point in using the notifier thing if you can
> > achieve basically the same without using it. :-)
> 
> sure, I just didn't want to mix printk internals with PM internals.
> that would put us in position of verifying future PM changes from
> printk-kthread point of view as well; and it can be quite complex,
> because printk offloading brings in big guns like scheduler and
> timekeeping. so the notifiers interface looks like a good
> alternative, besides those notifications happen early (and late)
> enough to keep us on the safe side.
> 
> well, I may be wrong.

I prefer direct invocations, becasue they generally allow to figure out
what's going on by simply following the code instead of having to
track all of the users of the notifiers to see what they may have
registered.

Moreover, the ordering of what happens is clear then, whereas with notifiers it
depends on the registration ordering and the entry and exit path orderings of
notifiers are the same which may be problematic sometimes.

In fact, the PM notifiers are mostly for stuff that cannot be done with frozen
user space and surely not for core subsystems.

Let alone that adding two lines of code is better than adding 50 lines for the
same purpose IMO ...

Thanks,
Rafael

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: [RFC][PATCHv5 06/13] printk: register PM notifier
  2017-08-17 15:43           ` Rafael J. Wysocki
@ 2017-08-17 23:19             ` Sergey Senozhatsky
  0 siblings, 0 replies; 94+ messages in thread
From: Sergey Senozhatsky @ 2017-08-17 23:19 UTC (permalink / raw)
  To: Rafael J. Wysocki
  Cc: Sergey Senozhatsky, Sergey Senozhatsky, Petr Mladek,
	Steven Rostedt, Jan Kara, Andrew Morton, Peter Zijlstra,
	Eric Biederman, Greg Kroah-Hartman, Jiri Slaby, Pavel Machek,
	Andreas Mohr, Tetsuo Handa, linux-kernel

Hello,

On (08/17/17 17:43), Rafael J. Wysocki wrote:
[..]
> > > In that case I would call printk_emergency_begin_sync() from
> > > dpm_prepare() and printk_emergency_end_sync() from dpm_complete().
> > 
> > hm, isn't it the case that dpm_prepare/dpm_complete are invoked only
> > by hibernate path? or does suspend path (s2ram, etc.) also calls
> > dpm_prepare/dpm_complete?
> 
> Yes, it does.

oh, good.

> > the 3 things we need to have (in PM context) for offloading:
> > - unparked printk kthread
> > - running scheduler
> > - online non-boot CPUs (on a UP system, or with non-boot CPUs disabled,
> >   offloading is a bit questionable)
> > 
> > - hm, may be something else...
> 
> All of that is there during the entire device suspend/resume including
> dpm_suspend/resume_noirq().
>
> But probably dpm_prepare/complete() are better places for the hooks at
> least for now.

ok, thanks.

> > > I just don't see much point in using the notifier thing if you can
> > > achieve basically the same without using it. :-)
> > 
> > sure, I just didn't want to mix printk internals with PM internals.
> > that would put us in position of verifying future PM changes from
> > printk-kthread point of view as well; and it can be quite complex,
> > because printk offloading brings in big guns like scheduler and
> > timekeeping. so the notifiers interface looks like a good
> > alternative, besides those notifications happen early (and late)
> > enough to keep us on the safe side.
> > 
> > well, I may be wrong.
> 
> I prefer direct invocations, becasue they generally allow to figure out
> what's going on by simply following the code instead of having to
> track all of the users of the notifiers to see what they may have
> registered.

I see the point: notifiers, in some sense, help us to alter sub-systems
without ever touching them or even explaining anything to the maintainers.
we just register a notifier and all of a sudden sub-system FOO begins to
execute our code at some point. all done entirely with in the printk.c file.
there is some power/flexibility and, perhaps, beauty in it, but there is
also some potential for abuse/wrongdoing in it. if direct calls work better
for you (and PM), then no objections from my side :)

> Moreover, the ordering of what happens is clear then, whereas with notifiers it
> depends on the registration ordering and the entry and exit path orderings of
> notifiers are the same which may be problematic sometimes.
> 
> In fact, the PM notifiers are mostly for stuff that cannot be done with frozen
> user space and surely not for core subsystems.
> 
> Let alone that adding two lines of code is better than adding 50 lines for the
> same purpose IMO ...

ok. I can rework the PM patch and get rid of notifiers for the next
submission (unless there will be objections from others). will take
a look.

thanks!

	-ss

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: [RFC][PATCHv5 00/13] printk: introduce printing kernel thread
  2017-08-15  2:56 [RFC][PATCHv5 00/13] printk: introduce printing kernel thread Sergey Senozhatsky
                   ` (12 preceding siblings ...)
  2017-08-15  2:56 ` [RFC][PATCHv5 13/13] printk: move offloading logic to per-cpu Sergey Senozhatsky
@ 2017-08-23  8:33 ` Sergey Senozhatsky
  2017-08-28  9:05 ` printk: what is going on with additional newlines? Pavel Machek
  14 siblings, 0 replies; 94+ messages in thread
From: Sergey Senozhatsky @ 2017-08-23  8:33 UTC (permalink / raw)
  To: Sergey Senozhatsky
  Cc: Petr Mladek, Steven Rostedt, Jan Kara, Andrew Morton,
	Peter Zijlstra, Rafael J . Wysocki, Eric Biederman,
	Greg Kroah-Hartman, Jiri Slaby, Pavel Machek, Andreas Mohr,
	Tetsuo Handa, linux-kernel, Sergey Senozhatsky

On (08/15/17 11:56), Sergey Senozhatsky wrote:
> Sergey Senozhatsky (13):
>   printk: move printk_pending out of per-cpu
>   printk: introduce printing kernel thread
>   printk: add sync printk_emergency API
>   printk: add enforce_emergency parameter
>   printk: enable printk offloading
>   printk: register PM notifier
>   printk: register syscore notifier
>   printk: set watchdog_thresh as maximum value for atomic_print_limit
>   printk: add auto-emergency enforcement mechanism
>   printk: force printk_kthread to offload printing
>   printk: always offload printing from user-space processes
>   printk: do not cond_resched() when we can offload
>   printk: move offloading logic to per-cpu


+ one more RFC patch
  the patch attempts to move offloading from potentially unsafe/critical
  sections which are not covered by emergency_begin/end. namely, those
  loops that explicitly silent watchdog.

I think, printk and watchdog should know more about each other.

=== 8< === 8< ===

From: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
Subject: [PATCH] printk: add offloading watchdog API

Introduce printk_offloading watchdog API to control the behaviour
of offloading. Some of the control paths, basically, disable the
soft-lockup watchdog by calling touch_all_softlockup_watchdogs().
One such example could be sysrq-t:

	__handle_sysrq()
	 sysrq_handle_showstate()
	  show_state()
	   show_state_filter()
	    touch_all_softlockup_watchdogs()

This control path deliberately and forcibly silent the watchdog
for various reasons, one of which is the fact that sysrq-t may
be called when system is in bad condition and we need to print
backtraces as soon as possible. In this case calling into the
scheduler from printk offloading may be dangerous and in general
should be avoided; besides we don't need to offload anything as
long as watchdog is happy.

This patch adds touch_printk_offloading_watchdog() call to
watchdog's touch_softlockup_watchdog(), so each time a control
path resets watchdog it also resets the printk offloading timestamp,
effective disabling printing offloading.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 include/linux/console.h |  2 ++
 kernel/printk/printk.c  | 39 ++++++++++++++++++++++++++++++++++-----
 kernel/watchdog.c       |  6 +++++-
 3 files changed, 41 insertions(+), 6 deletions(-)

diff --git a/include/linux/console.h b/include/linux/console.h
index 8ce29b2381d2..7408a345f4b1 100644
--- a/include/linux/console.h
+++ b/include/linux/console.h
@@ -191,6 +191,8 @@ extern void printk_emergency_begin(void);
 extern void printk_emergency_end(void);
 extern int printk_emergency_begin_sync(void);
 extern int printk_emergency_end_sync(void);
+extern void touch_printk_offloading_watchdog(void);
+extern void touch_printk_offloading_watchdog_on_cpu(unsigned int cpu);
 
 int mda_console_init(void);
 void prom_con_init(void);
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 369e0530a84f..a4e3f84ef365 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -476,6 +476,15 @@ module_param_named(atomic_print_limit, atomic_print_limit, uint, 0644);
 MODULE_PARM_DESC(atomic_print_limit,
 		 "the number of seconds task is allowed to print messages");
 
+/*
+ * Current printing task, timestamp when it has started printing
+ * loop and its scheduler stats. We use it to control offloading,
+ * see console_offload_printing() for details.
+ */
+static DEFINE_PER_CPU(struct task_struct, *printing_task);
+static DEFINE_PER_CPU(unsigned long, printing_start_ts);
+static DEFINE_PER_CPU(unsigned long, saved_csw);
+
 static inline bool printk_offloading_enabled(void)
 {
 	return atomic_print_limit &&
@@ -568,6 +577,26 @@ static inline unsigned long emergency_timeout(unsigned long now,
 	return time_after_eq(now, ts + 10 * atomic_print_limit);
 }
 
+/*
+ * Must be called by the watchdog. When control path calls
+ * touch_all_softlockup_watchdogs() or touch_softlockup_watchdog()
+ * to silent the watchdog we need to also reset the printk
+ * offloading counter in order to avoid printk offloading from a
+ * potentially unsafe context.
+ *
+ * preemption must be disabled.
+ */
+void touch_printk_offloading_watchdog(void)
+{
+	this_cpu_write(printing_start_ts, local_clock() >> 30LL);
+}
+
+/* Same as above, but updates`printing_start_ts' on a particular CPU. */
+void touch_printk_offloading_watchdog_on_cpu(unsigned int cpu)
+{
+	per_cpu(printing_start_ts, cpu) = local_clock() >> 30LL;
+}
+
 /*
  * Under heavy printing load or with a slow serial console (or both)
  * console_unlock() can stall CPUs, which can result in soft/hard-lockups,
@@ -579,9 +608,6 @@ static inline unsigned long emergency_timeout(unsigned long now,
  */
 static inline bool console_offload_printing(void)
 {
-	static DEFINE_PER_CPU(struct task_struct, *printing_task);
-	static DEFINE_PER_CPU(unsigned long, printing_start_ts);
-	static DEFINE_PER_CPU(unsigned long, saved_csw);
 	unsigned long now = local_clock() >> 30LL; /* seconds */
 
 	if (printk_kthread_should_stop())
@@ -602,7 +628,7 @@ static inline bool console_offload_printing(void)
 
 	/* A new task - reset the counters. */
 	if (this_cpu_read(printing_task) != current) {
-		this_cpu_write(printing_start_ts, local_clock() >> 30LL);
+		touch_printk_offloading_watchdog();
 		this_cpu_write(saved_csw, current->nvcsw + current->nivcsw);
 		this_cpu_write(printing_task, current);
 		return false;
@@ -628,7 +654,7 @@ static inline bool console_offload_printing(void)
 		 * back to console_unlock(), it will have another full
 		 * `atomic_print_limit' time slice.
 		 */
-		this_cpu_write(printing_start_ts, local_clock() >> 30LL);
+		touch_printk_offloading_watchdog();
 		return true;
 	}
 
@@ -2114,6 +2140,9 @@ EXPORT_SYMBOL_GPL(printk_emergency_end_sync);
 
 static inline bool console_offload_printing(void) { return false; }
 
+void touch_printk_offloading_watchdog(void) {}
+void touch_printk_offloading_watchdog_on_cpu(unsigned int cpu) {}
+
 #endif /* CONFIG_PRINTK */
 
 #ifdef CONFIG_EARLY_PRINTK
diff --git a/kernel/watchdog.c b/kernel/watchdog.c
index f5d52024f6b7..76c60df4b508 100644
--- a/kernel/watchdog.c
+++ b/kernel/watchdog.c
@@ -24,6 +24,7 @@
 #include <linux/workqueue.h>
 #include <linux/sched/clock.h>
 #include <linux/sched/debug.h>
+#include <linux/console.h>
 
 #include <asm/irq_regs.h>
 #include <linux/kvm_para.h>
@@ -268,6 +269,7 @@ void touch_softlockup_watchdog_sched(void)
 
 void touch_softlockup_watchdog(void)
 {
+	touch_printk_offloading_watchdog();
 	touch_softlockup_watchdog_sched();
 	wq_watchdog_touch(raw_smp_processor_id());
 }
@@ -282,8 +284,10 @@ void touch_all_softlockup_watchdogs(void)
 	 * do we care if a 0 races with a timestamp?
 	 * all it means is the softlock check starts one cycle later
 	 */
-	for_each_watchdog_cpu(cpu)
+	for_each_watchdog_cpu(cpu) {
 		per_cpu(watchdog_touch_ts, cpu) = 0;
+		touch_printk_offloading_watchdog_on_cpu(cpu);
+	}
 	wq_watchdog_touch(-1);
 }
 
-- 
2.14.1

^ permalink raw reply	[flat|nested] 94+ messages in thread

* printk: what is going on with additional newlines?
  2017-08-15  2:56 [RFC][PATCHv5 00/13] printk: introduce printing kernel thread Sergey Senozhatsky
                   ` (13 preceding siblings ...)
  2017-08-23  8:33 ` [RFC][PATCHv5 00/13] printk: introduce printing kernel thread Sergey Senozhatsky
@ 2017-08-28  9:05 ` Pavel Machek
  2017-08-28 10:28   ` Sergey Senozhatsky
  2017-08-29 16:48   ` Linus Torvalds
  14 siblings, 2 replies; 94+ messages in thread
From: Pavel Machek @ 2017-08-28  9:05 UTC (permalink / raw)
  To: Sergey Senozhatsky
  Cc: Petr Mladek, Steven Rostedt, Jan Kara, Andrew Morton, Jiri Slaby,
	Andreas Mohr, Tetsuo Handa, linux-kernel, Sergey Senozhatsky

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

Hi!

In 4.13-rc, printk("foo"); printk("bar"); seems to produce
foo\nbar. That's... quite surprising/unwelcome. What is going on
there? Are timestamps responsible?

									Pavel
									
-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 181 bytes --]

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-08-28  9:05 ` printk: what is going on with additional newlines? Pavel Machek
@ 2017-08-28 10:28   ` Sergey Senozhatsky
  2017-08-28 12:21     ` Sergey Senozhatsky
  2017-08-29 16:48   ` Linus Torvalds
  1 sibling, 1 reply; 94+ messages in thread
From: Sergey Senozhatsky @ 2017-08-28 10:28 UTC (permalink / raw)
  To: Pavel Machek
  Cc: Sergey Senozhatsky, Petr Mladek, Steven Rostedt, Jan Kara,
	Andrew Morton, Jiri Slaby, Andreas Mohr, Tetsuo Handa,
	linux-kernel, Sergey Senozhatsky

On (08/28/17 11:05), Pavel Machek wrote:
> Hi!
> 
> In 4.13-rc, printk("foo"); printk("bar"); seems to produce
> foo\nbar. That's... quite surprising/unwelcome. What is going on
> there? Are timestamps responsible?

well, one thing we know for sure it is not related to this patch set  ;)


does any of the below patches fix the problem for you?

basically it sets up the rule -- if we don't have LOG_NEWLINE lflags
then we enforce LOG_CONT.

---

@@ -1721,9 +1723,13 @@ asmlinkage int vprintk_emit(int facility, int level,
 	text_len = vscnprintf(text, sizeof(textbuf), fmt, args);
 
 	/* mark and strip a trailing newline */
-	if (text_len && text[text_len-1] == '\n') {
-		text_len--;
-		lflags |= LOG_NEWLINE;
+	if (text_len) {
+		if (text[text_len-1] == '\n') {
+			text_len--;
+			lflags |= LOG_NEWLINE;
+		} else {
+			lflags |= LOG_CONT;
+		}
 	}
 
 	/* strip kernel syslog prefix and extract log level or control flags */


---


=== 8< === 8< ===


or... an alternative "solution"

---

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index fc47863f629c..5fd567abc5e6 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1670,7 +1670,9 @@ static size_t log_output(int facility, int level, enum log_flags lflags, const c
 	 * write from the same process, try to add it to the buffer.
 	 */
 	if (cont.len) {
-		if (cont.owner == current && (lflags & LOG_CONT)) {
+		if (cont.owner == current &&
+				((lflags & LOG_CONT) ||
+				 !(lflags & LOG_NEWLINE))) {
 			if (cont_add(facility, level, lflags, text, text_len))
 				return text_len;
 		}


---

	-ss

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-08-28 10:28   ` Sergey Senozhatsky
@ 2017-08-28 12:21     ` Sergey Senozhatsky
  2017-08-28 12:38       ` Sergey Senozhatsky
  2017-08-28 12:46       ` Pavel Machek
  0 siblings, 2 replies; 94+ messages in thread
From: Sergey Senozhatsky @ 2017-08-28 12:21 UTC (permalink / raw)
  To: Sergey Senozhatsky
  Cc: Pavel Machek, Sergey Senozhatsky, Petr Mladek, Steven Rostedt,
	Jan Kara, Andrew Morton, Jiri Slaby, Andreas Mohr, Tetsuo Handa,
	linux-kernel

On (08/28/17 19:28), Sergey Senozhatsky wrote:
> On (08/28/17 11:05), Pavel Machek wrote:
> > Hi!
> > 
> > In 4.13-rc, printk("foo"); printk("bar"); seems to produce
> > foo\nbar. That's... quite surprising/unwelcome. What is going on
> > there? Are timestamps responsible?
> 
> well, one thing we know for sure it is not related to this patch set  ;)
> 
> 
> does any of the below patches fix the problem for you?
> 
> basically it sets up the rule -- if we don't have LOG_NEWLINE lflags
> then we enforce LOG_CONT.

[..]

> @@ -1670,7 +1670,9 @@ static size_t log_output(int facility, int level, enum log_flags lflags, const c
>  	 * write from the same process, try to add it to the buffer.
>  	 */
>  	if (cont.len) {
> 		if (cont.owner == current && (lflags & LOG_CONT)) {


on the other hand... I don't think I like that check at all.
so I *probably* want to change it to -- !LOG_NEWLINE messages of the
same loglevel AND from the same task are getting concatenated.
a message with LOG_NEWLINE flushes the cont buffer.

for example:

       printk("foo"); printk("foo"); printk("bar\n");
       printk("buz"); printk("buz"); printk("buz"); pr_info("INFO msg\n");
       printk("buz"); printk("buz"); printk("buz"); pr_err("ERR msg\n");
       printk(KERN_CONT"foo"); printk(KERN_CONT"foo"); printk(KERN_CONT"bar\n");
       printk(KERN_CONT"foo"); printk(KERN_CONT"foo"); printk(KERN_ERR"bar\n");
       printk(KERN_CONT"foo"); printk(KERN_ERR"foo err"); printk(KERN_ERR"bar err\n");


for instance,
	printk(KERN_ERR"foo err"); printk(KERN_ERR"bar err\n");

should produce    "foo errbar err\n".    from the same task and of
the same loglevel, no new line. must be cont messages with a missing
KERN_CONT. right?


so, for the examples I posted above, I think, the output must be

 foofoobar
 buzbuzbuz
 INFO msg
 buzbuzbuz
 ERR msg
 foofoobar
 foofoo
 bar
 foo
 foo errbar err


how about something like this?

---

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index fc47863f629c..675febf84dc8 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1670,10 +1670,9 @@ static size_t log_output(int facility, int level, enum log_flags lflags, const c
 	 * write from the same process, try to add it to the buffer.
 	 */
 	if (cont.len) {
-		if (cont.owner == current && (lflags & LOG_CONT)) {
+		if (cont.owner == current && cont.level == level)
 			if (cont_add(facility, level, lflags, text, text_len))
 				return text_len;
-		}
 		/* Otherwise, make sure it's flushed */
 		cont_flush();
 	}
 

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-08-28 12:21     ` Sergey Senozhatsky
@ 2017-08-28 12:38       ` Sergey Senozhatsky
  2017-08-28 12:46       ` Pavel Machek
  1 sibling, 0 replies; 94+ messages in thread
From: Sergey Senozhatsky @ 2017-08-28 12:38 UTC (permalink / raw)
  To: Sergey Senozhatsky
  Cc: Pavel Machek, Sergey Senozhatsky, Petr Mladek, Steven Rostedt,
	Jan Kara, Andrew Morton, Jiri Slaby, Andreas Mohr, Tetsuo Handa,
	linux-kernel

On (08/28/17 21:21), Sergey Senozhatsky wrote:
> how about something like this?
> 

...ok, definetely breaks the

	KERN_ERR "foo"; KERN_CONT "bar"; KERN_CONT "bar"; KERN_CONT "\n";

case. um... something like this then?

---

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index fc47863f629c..098e280e9fe0 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1670,10 +1670,11 @@ static size_t log_output(int facility, int level, enum log_flags lflags, const c
 	 * write from the same process, try to add it to the buffer.
 	 */
 	if (cont.len) {
-		if (cont.owner == current && (lflags & LOG_CONT)) {
+		if (cont.owner == current &&
+				((cont.level == level) ||
+				(lflags & LOG_CONT)))
 			if (cont_add(facility, level, lflags, text, text_len))
 				return text_len;
-		}
 		/* Otherwise, make sure it's flushed */
 		cont_flush();
 	}
 

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-08-28 12:21     ` Sergey Senozhatsky
  2017-08-28 12:38       ` Sergey Senozhatsky
@ 2017-08-28 12:46       ` Pavel Machek
  2017-08-29 13:40         ` Sergey Senozhatsky
  1 sibling, 1 reply; 94+ messages in thread
From: Pavel Machek @ 2017-08-28 12:46 UTC (permalink / raw)
  To: Sergey Senozhatsky
  Cc: Sergey Senozhatsky, Petr Mladek, Steven Rostedt, Jan Kara,
	Andrew Morton, Jiri Slaby, Andreas Mohr, Tetsuo Handa,
	linux-kernel

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

Hi!

On Mon 2017-08-28 21:21:09, Sergey Senozhatsky wrote:
> On (08/28/17 19:28), Sergey Senozhatsky wrote:
> > On (08/28/17 11:05), Pavel Machek wrote:
> > > Hi!
> > > 
> > > In 4.13-rc, printk("foo"); printk("bar"); seems to produce
> > > foo\nbar. That's... quite surprising/unwelcome. What is going on
> > > there? Are timestamps responsible?
> > 
> > well, one thing we know for sure it is not related to this patch set  ;)
> > 
> > 
> > does any of the below patches fix the problem for you?
> > 
> > basically it sets up the rule -- if we don't have LOG_NEWLINE lflags
> > then we enforce LOG_CONT.
> 
> [..]
> 
> > @@ -1670,7 +1670,9 @@ static size_t log_output(int facility, int level, enum log_flags lflags, const c
> >  	 * write from the same process, try to add it to the buffer.
> >  	 */
> >  	if (cont.len) {
> > 		if (cont.owner == current && (lflags & LOG_CONT)) {
> 
> 
> on the other hand... I don't think I like that check at all.
> so I *probably* want to change it to -- !LOG_NEWLINE messages of the
> same loglevel AND from the same task are getting concatenated.
> a message with LOG_NEWLINE flushes the cont buffer.

Looks good to me.

> for example:
> 
>        printk("foo"); printk("foo"); printk("bar\n");

This behaviour is important for me... and this sounds ok.

>        printk("buz"); printk("buz"); printk("buz"); pr_info("INFO msg\n");
>        printk("buz"); printk("buz"); printk("buz"); pr_err("ERR msg\n");
>        printk(KERN_CONT"foo"); printk(KERN_CONT"foo"); printk(KERN_CONT"bar\n");
>        printk(KERN_CONT"foo"); printk(KERN_CONT"foo"); printk(KERN_ERR"bar\n");
>        printk(KERN_CONT"foo"); printk(KERN_ERR"foo err"); printk(KERN_ERR"bar err\n");
>

> 
> for instance,
> 	printk(KERN_ERR"foo err"); printk(KERN_ERR"bar err\n");
> 
> should produce    "foo errbar err\n".    from the same task and of
> the same loglevel, no new line. must be cont messages with a missing
> KERN_CONT. right?

Not sure. Historically it produce foo err<9>bar err\n. Concatening is
probably okay.

> how about something like this?

Umm.. No?

printk(KERN_INFO "foo"); printk(KERN_CONT "bar\n");

should produce "foobar\n", right? Will not your patch insert newline
there?

								Pavel

> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index fc47863f629c..675febf84dc8 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -1670,10 +1670,9 @@ static size_t log_output(int facility, int level, enum log_flags lflags, const c
>  	 * write from the same process, try to add it to the buffer.
>  	 */
>  	if (cont.len) {
> -		if (cont.owner == current && (lflags & LOG_CONT)) {
> +		if (cont.owner == current && cont.level == level)
>  			if (cont_add(facility, level, lflags, text, text_len))
>  				return text_len;
> -		}
>  		/* Otherwise, make sure it's flushed */
>  		cont_flush();
>  	}
>  

-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 181 bytes --]

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-08-28 12:46       ` Pavel Machek
@ 2017-08-29 13:40         ` Sergey Senozhatsky
  2017-08-29 16:37           ` Joe Perches
  2017-08-29 17:00           ` Linus Torvalds
  0 siblings, 2 replies; 94+ messages in thread
From: Sergey Senozhatsky @ 2017-08-29 13:40 UTC (permalink / raw)
  To: Pavel Machek
  Cc: Sergey Senozhatsky, Sergey Senozhatsky, Petr Mladek,
	Steven Rostedt, Jan Kara, Andrew Morton, Jiri Slaby,
	Andreas Mohr, Tetsuo Handa, linux-kernel

Hi,

so I had a second look, and I think the patch I posted yesterday is
pretty wrong. How about something like below?

---

>From d65d1b74d3acc51e5d998c5d2cf10d20c28dc2f9 Mon Sep 17 00:00:00 2001
From: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
Date: Tue, 29 Aug 2017 22:30:07 +0900
Subject: [PATCH] printk: restore non-log_prefix messages handling

Pavel reported that
	printk("foo"); printk("bar");

now does not produce a single continuation "foobar" line, but
instead produces two lines
		foo
		bar

The first printk() goes to cont buffer, just as before. The difference
is how we handle the second one. We used to just add it to the cont
buffer:

	if (!(lflags & LOG_NEWLINE)) {
		if (cont.len && (lflags & LOG_PREFIX || cont.owner != current))
			cont_flush();

		cont_add(...)
	}

but now we flush the existing cont buffer and store the second
printk() message separately:

	if (cont.len) {
		if (cont.owner == current && (lflags & LOG_CONT))
			return cont_add();

		/* otherwise flush */
		cont_flush();
	}

because printk("bar") does not have LOG_CONT.

The patch restores the old behaviour.

To verify the change I did the following printk() test again the v4.5
and patched linux-next:

 pr_err("foo"); pr_cont("bar"); pr_cont("bar\n");
 printk("foo"); printk("foo"); printk("bar\n");

 printk("baz"); printk("baz"); printk("baz"); pr_info("INFO foo");
 printk("baz"); printk("baz"); printk("baz"); pr_err("ERR foo");

 printk(KERN_CONT"foo"); printk(KERN_CONT"foo"); printk(KERN_CONT"bar\n");
 printk(KERN_CONT"foo"); printk(KERN_CONT"foo"); printk(KERN_ERR"bar\n");

 printk(KERN_CONT"foo"); printk(KERN_ERR"foo err"); printk(KERN_ERR "ERR foo\n");

 printk("baz"); printk("baz"); printk("baz"); pr_info("INFO foo\n");
 printk("baz"); printk("baz"); printk("baz"); pr_err("ERR foo\n");

 printk(KERN_INFO "foo"); printk(KERN_CONT "bar\n"); printk(KERN_CONT "bar\n");

I, however, got a slightly different output (I'll explain the difference):

	v4.5                    linux-next

	foobarbar               foobarbar
	foofoobar               foofoobar
	bazbazbaz               bazbazbaz
	INFO foo                INFO foobazbazbaz
	bazbazbaz
	ERR foo                 ERR foofoofoobar
	foofoobar
	foofoo                  foofoo
	bar                     bar
	foo                     foo
	foo err                 foo err
	ERR foo                 ERR foo
	bazbazbaz               bazbazbaz
	INFO foo                INFO foo
	bazbazbaz               bazbazbaz
	ERR foo                 ERR foo
	foobar                  foobar
	bar                     bar

As we can see the difference is in:
   pr_info("INFO foo"); printk(KERN_CONT"foo"); printk(KERN_CONT"foo")...
and
   pr_err("ERR foo"); printk(KERN_CONT"foo"); printk(KERN_CONT"foo");...
handling.

The output is expected to be two continuation lines; but this is not
the case for old kernels.

What the old kernel does here is:

- it sees that cont buffer already has data: all those !LOG_PREFIX messages

- it also sees that the current messages is LOG_PREFIX and that part of
  the cont buffer was already printed to the serial console:

	// Flush the conflicting buffer. An earlier newline was missing
	// or another task also prints continuation lines

	if (!(lflags & LOG_NEWLINE)) {
		if (cont.len && (lflags & LOG_PREFIX || cont.owner != current))
			cont_flush(LOG_NEWLINE);

		if (cont_add(text))
			printed_len += text_len;
		else
			printed_len += log_store(text);
	}

  the problem here is that, flush does not actually flush the buffer and
  does not reset the conf buffer state, but sets cont.flushed to true
  instead:

	if (cont.cons) {
		log_store(cont.text);
		cont.flags = flags;
		cont.flushed = true;
	}

- then the kernel attempts to cont_add() the messages. but cont_add() does
  not append the messages to the cont buffer, because of this check

	if (cont.len && cont.flushed)
		return false;

  both cont.len and cont.flushed are true. because the kernel waits for
  console_unlock() to call console_cont_flush()->cont_print_text(),
  which should print the cont.text to the serial console and reset the
  cont buffer state.

- but cont_print_text() must be called under logbuf_lock lock, which
  we still hold in vprintk_emit(). so the kernel has no chance to flush
  the cont buffer and thus cont_add() fails there and forces the kernel
  to log_store() the message, allocating a separate logbuf entry for
  it.

That's why we see the difference in v4.5 vs linux-next logs. This is
visible only when !LOG_NEWLINE path has to cont_flush() partially
printed cont buffer from under the logbuf_lock.

I think the old behavior had a bug - we need to concatenate

	KERN_ERR foo; KERN_CONT bar; KERN_CON bar\n;

regardless the previous cont buffer state.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
Reported-by: Pavel Machek <pavel@ucw.cz>
---
 kernel/printk/printk.c | 11 ++++++++---
 1 file changed, 8 insertions(+), 3 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index ac1fd606d6c5..be868b7d9ceb 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1914,12 +1914,17 @@ static size_t log_output(int facility, int level, enum log_flags lflags, const c
 	 * write from the same process, try to add it to the buffer.
 	 */
 	if (cont.len) {
-		if (cont.owner == current && (lflags & LOG_CONT)) {
+		/*
+		 * Flush the conflicting buffer. An earlier newline was missing,
+		 * or another task also prints continuation lines.
+		 */
+		if (lflags & LOG_PREFIX || cont.owner != current)
+			cont_flush();
+
+		if (!(lflags & LOG_PREFIX) || lflags & LOG_CONT) {
 			if (cont_add(facility, level, lflags, text, text_len))
 				return text_len;
 		}
-		/* Otherwise, make sure it's flushed */
-		cont_flush();
 	}
 
 	/* Skip empty continuation lines that couldn't be added - they just flush */
-- 
2.14.1

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-08-29 13:40         ` Sergey Senozhatsky
@ 2017-08-29 16:37           ` Joe Perches
  2017-08-29 17:00           ` Linus Torvalds
  1 sibling, 0 replies; 94+ messages in thread
From: Joe Perches @ 2017-08-29 16:37 UTC (permalink / raw)
  To: Sergey Senozhatsky, Pavel Machek, Linus Torvalds
  Cc: Sergey Senozhatsky, Petr Mladek, Steven Rostedt, Jan Kara,
	Andrew Morton, Jiri Slaby, Andreas Mohr, Tetsuo Handa,
	linux-kernel

On Tue, 2017-08-29 at 22:40 +0900, Sergey Senozhatsky wrote:
> Hi,
> 
> so I had a second look, and I think the patch I posted yesterday is
> pretty wrong. How about something like below?

> ---
> 
> From d65d1b74d3acc51e5d998c5d2cf10d20c28dc2f9 Mon Sep 17 00:00:00 2001
> From: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> Date: Tue, 29 Aug 2017 22:30:07 +0900
> Subject: [PATCH] printk: restore non-log_prefix messages handling
> 
> Pavel reported that
> 	printk("foo"); printk("bar");
> 
> now does not produce a single continuation "foobar" line, but
> instead produces two lines
> 		foo
> 		bar
> 
> The first printk() goes to cont buffer, just as before. The difference
> is how we handle the second one. We used to just add it to the cont
> buffer:
> 
> 	if (!(lflags & LOG_NEWLINE)) {
> 		if (cont.len && (lflags & LOG_PREFIX || cont.owner != current))
> 			cont_flush();
> 
> 		cont_add(...)
> 	}
> 
> but now we flush the existing cont buffer and store the second
> printk() message separately:
> 
> 	if (cont.len) {
> 		if (cont.owner == current && (lflags & LOG_CONT))
> 			return cont_add();
> 
> 		/* otherwise flush */
> 		cont_flush();
> 	}
> 
> because printk("bar") does not have LOG_CONT.
> 
> The patch restores the old behaviour.
> 
> To verify the change I did the following printk() test again the v4.5
> and patched linux-next:

It's possibly dubious to go back to v4.5 behavior.
Linus changed the
printk continuation behavior in v4.9
Unfortunately he did this without
posting anything to lkml
for comment and he broke a bunch of continuation
printks.


>  pr_err("foo"); pr_cont("bar"); pr_cont("bar\n");
>  printk("foo"); printk("foo"); printk("bar\n");
> 
>  printk("baz"); printk("baz"); printk("baz"); pr_info("INFO foo");
>  printk("baz"); printk("baz"); printk("baz"); pr_err("ERR foo");
> 
>  printk(KERN_CONT"foo"); printk(KERN_CONT"foo"); printk(KERN_CONT"bar\n");
>  printk(KERN_CONT"foo"); printk(KERN_CONT"foo"); printk(KERN_ERR"bar\n");
> 
>  printk(KERN_CONT"foo"); printk(KERN_ERR"foo err"); printk(KERN_ERR "ERR foo\n");
> 
>  printk("baz"); printk("baz"); printk("baz"); pr_info("INFO foo\n");
>  printk("baz"); printk("baz"); printk("baz"); pr_err("ERR foo\n");
> 
>  printk(KERN_INFO "foo"); printk(KERN_CONT "bar\n"); printk(KERN_CONT "bar\n");
> 
> I, however, got a slightly different output (I'll explain the difference):
> 
> 	v4.5                    linux-next
> 
> 	foobarbar               foobarbar
> 	foofoobar               foofoobar
> 	bazbazbaz               bazbazbaz
> 	INFO foo                INFO foobazbazbaz
> 	bazbazbaz
> 	ERR foo                 ERR foofoofoobar
> 	foofoobar
> 	foofoo                  foofoo
> 	bar                     bar
> 	foo                     foo
> 	foo err                 foo err
> 	ERR foo                 ERR foo
> 	bazbazbaz               bazbazbaz
> 	INFO foo                INFO foo
> 	bazbazbaz               bazbazbaz
> 	ERR foo                 ERR foo
> 	foobar                  foobar
> 	bar                     bar
> 
> As we can see the difference is in:
>    pr_info("INFO foo"); printk(KERN_CONT"foo"); printk(KERN_CONT"foo")...
> and
>    pr_err("ERR foo"); printk(KERN_CONT"foo"); printk(KERN_CONT"foo");...
> handling.
> 
> The output is expected to be two continuation lines; but this is not
> the case for old kernels.
> 
> What the old kernel does here is:
> 
> - it sees that cont buffer already has data: all those !LOG_PREFIX messages
> 
> - it also sees that the current messages is LOG_PREFIX and that part of
>   the cont buffer was already printed to the serial console:
> 
> 	// Flush the conflicting buffer. An earlier newline was missing
> 	// or another task also prints continuation lines
> 
> 	if (!(lflags & LOG_NEWLINE)) {
> 		if (cont.len && (lflags & LOG_PREFIX || cont.owner != current))
> 			cont_flush(LOG_NEWLINE);
> 
> 		if (cont_add(text))
> 			printed_len += text_len;
> 		else
> 			printed_len += log_store(text);
> 	}
> 
>   the problem here is that, flush does not actually flush the buffer and
>   does not reset the conf buffer state, but sets cont.flushed to true
>   instead:
> 
> 	if (cont.cons) {
> 		log_store(cont.text);
> 		cont.flags = flags;
> 		cont.flushed = true;
> 	}
> 
> - then the kernel attempts to cont_add() the messages. but cont_add() does
>   not append the messages to the cont buffer, because of this check
> 
> 	if (cont.len && cont.flushed)
> 		return false;
> 
>   both cont.len and cont.flushed are true. because the kernel waits for
>   console_unlock() to call console_cont_flush()->cont_print_text(),
>   which should print the cont.text to the serial console and reset the
>   cont buffer state.
> 
> - but cont_print_text() must be called under logbuf_lock lock, which
>   we still hold in vprintk_emit(). so the kernel has no chance to flush
>   the cont buffer and thus cont_add() fails there and forces the kernel
>   to log_store() the message, allocating a separate logbuf entry for
>   it.
> 
> That's why we see the difference in v4.5 vs linux-next logs. This is
> visible only when !LOG_NEWLINE path has to cont_flush() partially
> printed cont buffer from under the logbuf_lock.
> 
> I think the old behavior had a bug - we need to concatenate
> 
> 	KERN_ERR foo; KERN_CONT bar; KERN_CON bar\n;
> 
> regardless the previous cont buffer state.
> 
> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> Reported-by: Pavel Machek <pavel@ucw.cz>
> ---
>  kernel/printk/printk.c | 11 ++++++++---
>  1 file changed, 8 insertions(+), 3 deletions(-)
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index ac1fd606d6c5..be868b7d9ceb 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -1914,12 +1914,17 @@ static size_t log_output(int facility, int level, enum log_flags lflags, const c
>  	 * write from the same process, try to add it to the buffer.
>  	 */
>  	if (cont.len) {
> -		if (cont.owner == current && (lflags & LOG_CONT)) {
> +		/*
> +		 * Flush the conflicting buffer. An earlier newline was missing,
> +		 * or another task also prints continuation lines.
> +		 */
> +		if (lflags & LOG_PREFIX || cont.owner != current)
> +			cont_flush();
> +
> +		if (!(lflags & LOG_PREFIX) || lflags & LOG_CONT) {
>  			if (cont_add(facility, level, lflags, text, text_len))
>  				return text_len;
>  		}
> -		/* Otherwise, make sure it's flushed */
> -		cont_flush();
>  	}
>  
>  	/* Skip empty continuation lines that couldn't be added - they just flush */

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-08-28  9:05 ` printk: what is going on with additional newlines? Pavel Machek
  2017-08-28 10:28   ` Sergey Senozhatsky
@ 2017-08-29 16:48   ` Linus Torvalds
  2017-08-29 17:10     ` Joe Perches
  2017-08-29 20:24     ` Pavel Machek
  1 sibling, 2 replies; 94+ messages in thread
From: Linus Torvalds @ 2017-08-29 16:48 UTC (permalink / raw)
  To: Pavel Machek
  Cc: Sergey Senozhatsky, Petr Mladek, Steven Rostedt, Jan Kara,
	Andrew Morton, Jiri Slaby, Andreas Mohr, Tetsuo Handa,
	Linux Kernel Mailing List, Sergey Senozhatsky

On Mon, Aug 28, 2017 at 2:05 AM, Pavel Machek <pavel@ucw.cz> wrote:
> Hi!
>
> In 4.13-rc, printk("foo"); printk("bar"); seems to produce
> foo\nbar. That's... quite surprising/unwelcome. What is going on
> there? Are timestamps responsible?

No.

It's actively trying to treach you not to do shit.

If you want to continue a line, you NEED to use KERN_CONT.

That has always been true. It hasn't always been enforced, though.

If you do two printk's and the second one doesn't say "I'm a
continuation", the printk logic assumes you're just confused and
wanted two lines.

And no, we are *NOT* adding code to printk to help people avoid this.
Quite the reverse.

Stop doing continuations at all please. But if you do, you'd better
use KERN_CONT. And if you don't, and you get multiple lines, it's your
own damn fault.

                 Linus

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-08-29 13:40         ` Sergey Senozhatsky
  2017-08-29 16:37           ` Joe Perches
@ 2017-08-29 17:00           ` Linus Torvalds
  2017-08-29 17:12             ` Linus Torvalds
  2017-08-29 17:33             ` Sergey Senozhatsky
  1 sibling, 2 replies; 94+ messages in thread
From: Linus Torvalds @ 2017-08-29 17:00 UTC (permalink / raw)
  To: Sergey Senozhatsky
  Cc: Pavel Machek, Sergey Senozhatsky, Petr Mladek, Steven Rostedt,
	Jan Kara, Andrew Morton, Jiri Slaby, Andreas Mohr, Tetsuo Handa,
	Linux Kernel Mailing List

On Tue, Aug 29, 2017 at 6:40 AM, Sergey Senozhatsky
<sergey.senozhatsky.work@gmail.com> wrote:
> Pavel reported that
>         printk("foo"); printk("bar");
>
> now does not produce a single continuation "foobar" line, but
> instead produces two lines
>                 foo
>                 bar

And that's the *correct* behavior.

Stop trying to fix that. Fix the printk's instead.

In particular, the

    printk("bar");

could have come from an interrupt, and have nothing what-so-ever to do
with "foo".

If you want continuations, you

 (a) make sure the first one doesn't end in a newline

 (b) make sure the second printk has a KERN_CONT

 (c) even after that, ask yourself how much you _really_ want
continuations, because there are going to be situations where it still
doesn't work.

I refuse to help those things. We mis-designed things, and the
continuations were a mistake to begin with, but they were a mistake
that was understandable in the timeframe they happened. But it's not
something we should support, and it's most definitely is not something
we should then say "oh, you were broken shit that didn't even bother
to add the KERN_CONT, let me help your crap".

No.

Only acceptable use of continuations is basically boot-time testing,
when you do things like

     printk("Testing feature XYZ..");
     this_may_blow_up_because_of_hw_bugs();
     printk(KERN_CONT " ... ok\n");

and anything else you should seriously try to marshal the data
*before* doing a printk(), and not expect printk() to marshal it for
you. But for legacy reasons, we do end up trying to support KERN_CONT.
Just barely.

I'd really like to get rid of it entirely, because the whole log-based
structure really really doesn't work well for it (what if somebody has
already read the partial line from the logs?)

Our printk stuff didn't used to be log-based. It was just a plain
character-based circular buffer. Back then that KERN_CONT made a whole
lot more sense.

              Linus

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-08-29 16:48   ` Linus Torvalds
@ 2017-08-29 17:10     ` Joe Perches
  2017-08-29 17:20       ` Linus Torvalds
  2017-08-29 20:24     ` Pavel Machek
  1 sibling, 1 reply; 94+ messages in thread
From: Joe Perches @ 2017-08-29 17:10 UTC (permalink / raw)
  To: Linus Torvalds, Pavel Machek
  Cc: Sergey Senozhatsky, Petr Mladek, Steven Rostedt, Jan Kara,
	Andrew Morton, Jiri Slaby, Andreas Mohr, Tetsuo Handa,
	Linux Kernel Mailing List, Sergey Senozhatsky

On Tue, 2017-08-29 at 09:48 -0700, Linus Torvalds wrote:
> On Mon, Aug 28, 2017 at 2:05 AM, Pavel Machek <pavel@ucw.cz> wrote:
> > Hi!
> > 
> > In 4.13-rc, printk("foo"); printk("bar"); seems to produce
> > foo\nbar. That's... quite surprising/unwelcome. What is going on
> > there? Are timestamps responsible?
> 
> No.
> 
> It's actively trying to treach you not to do shit.
> 
> If you want to continue a line, you NEED to use KERN_CONT.
> 
> That has always been true. It hasn't always been enforced, though.

That's simply false.

It was never true until you made it a requirement.
(it's not a bad requirement, but it did change behavior)

It was just unfortunate there were( and still are)
many cases that needed updating.

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-08-29 17:00           ` Linus Torvalds
@ 2017-08-29 17:12             ` Linus Torvalds
  2017-08-29 20:41               ` Tetsuo Handa
  2017-08-29 23:50               ` Steven Rostedt
  2017-08-29 17:33             ` Sergey Senozhatsky
  1 sibling, 2 replies; 94+ messages in thread
From: Linus Torvalds @ 2017-08-29 17:12 UTC (permalink / raw)
  To: Sergey Senozhatsky
  Cc: Pavel Machek, Sergey Senozhatsky, Petr Mladek, Steven Rostedt,
	Jan Kara, Andrew Morton, Jiri Slaby, Andreas Mohr, Tetsuo Handa,
	Linux Kernel Mailing List

On Tue, Aug 29, 2017 at 10:00 AM, Linus Torvalds
<torvalds@linux-foundation.org> wrote:
>
> I refuse to help those things. We mis-designed things

Actually, let me rephrase that:

It might actually be a good idea to help those things, by making
helper functions available that do the marshalling.

So not calling "printk()" directly, but having a set of simple
"buffer_print()" functions where each user has its own buffer, and
then the "buffer_print()" functions will help people do nicely output
data.

So if the issue is that people want to print (for example) hex dumps
one character at a time, but don't want to have each character show up
on a line of their own, I think we might well add a few functions to
help dop that.

But they wouldn't be "printk". They would be the buffering functions
that then call printk when tyhey have buffered a line.

That avoids the whole nasty issue with printk - printk wants to show
stuff early (because _maybe_ it's critical) and printk wants to make
log records with timestamps and loglevels. And printk has serious
locking issues that are really nasty and fundamental.

A private buffer has none of those issues.

                 Linus

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-08-29 17:10     ` Joe Perches
@ 2017-08-29 17:20       ` Linus Torvalds
  2017-08-29 17:33         ` Joe Perches
  0 siblings, 1 reply; 94+ messages in thread
From: Linus Torvalds @ 2017-08-29 17:20 UTC (permalink / raw)
  To: Joe Perches
  Cc: Pavel Machek, Sergey Senozhatsky, Petr Mladek, Steven Rostedt,
	Jan Kara, Andrew Morton, Jiri Slaby, Andreas Mohr, Tetsuo Handa,
	Linux Kernel Mailing List, Sergey Senozhatsky

On Tue, Aug 29, 2017 at 10:10 AM, Joe Perches <joe@perches.com> wrote:
> That's simply false.
>
> It was never true until you made it a requirement.
> (it's not a bad requirement, but it did change behavior)

Oh, it changed behavior, yes (and for kernel code we do that, and
require people to change).

But even before it was technically required, it was very much supposed
to be there as a marker. KERN_CONT has existed for about a decade.

It was added in commit 474925277671 ("printk: add KERN_CONT
annotation") back in 2007, with a comment that said - at that time:

  /*
   * Annotation for a "continued" line of log printout (only done after a
   * line that had no enclosing \n). Only to be used by core/arch code
   * during early bootup (a continued line is not SMP-safe otherwise).
   */

so basically for the last ten years, it's very much been policy that

 (a) you shouldn't do this except for during early bootiup

 (b) you should have that KERN_CONT marker to show that you're doing it

So this is *not* new.

What is new is the enforcement, because people didn't follow the rules
without it.

So yes, we're enforcing it now, and we're not going back to the
unenforced times, because a decade of shit has shown that people
didn't do it without being forced to.

                  Linus

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-08-29 17:20       ` Linus Torvalds
@ 2017-08-29 17:33         ` Joe Perches
  2017-08-29 17:36           ` Linus Torvalds
  0 siblings, 1 reply; 94+ messages in thread
From: Joe Perches @ 2017-08-29 17:33 UTC (permalink / raw)
  To: Linus Torvalds
  Cc: Pavel Machek, Sergey Senozhatsky, Petr Mladek, Steven Rostedt,
	Jan Kara, Andrew Morton, Jiri Slaby, Andreas Mohr, Tetsuo Handa,
	Linux Kernel Mailing List, Sergey Senozhatsky

On Tue, 2017-08-29 at 10:20 -0700, Linus Torvalds wrote:
> On Tue, Aug 29, 2017 at 10:10 AM, Joe Perches <joe@perches.com> wrote:
> > That's simply false.
> > 
> > It was never true until you made it a requirement.
> > (it's not a bad requirement, but it did change behavior)
> 
> Oh, it changed behavior, yes (and for kernel code we do that, and
> require people to change).
> 
> But even before it was technically required, it was very much supposed
> to be there as a marker. KERN_CONT has existed for about a decade.

Which is very much not "forever" in kernel terms.

> It was added in commit 474925277671 ("printk: add KERN_CONT
> annotation") back in 2007, with a comment that said - at that time:

Yeah, I remember things too.

>   /*
>    * Annotation for a "continued" line of log printout (only done after a
>    * line that had no enclosing \n). Only to be used by core/arch code
>    * during early bootup (a continued line is not SMP-safe otherwise).
>    */

And note the "core/arch code during bootup" bit.

Look, it's not fundamentally a "bad" requirement.
It was just not "always required".

And silently slipping in the change because you
were unhappy with adding newlines to some printks
was, at best, poor form.

Your change broke a bunch of output.

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-08-29 17:00           ` Linus Torvalds
  2017-08-29 17:12             ` Linus Torvalds
@ 2017-08-29 17:33             ` Sergey Senozhatsky
  2017-08-29 17:52               ` Linus Torvalds
  1 sibling, 1 reply; 94+ messages in thread
From: Sergey Senozhatsky @ 2017-08-29 17:33 UTC (permalink / raw)
  To: Linus Torvalds
  Cc: Sergey Senozhatsky, Pavel Machek, Sergey Senozhatsky,
	Petr Mladek, Steven Rostedt, Jan Kara, Andrew Morton, Jiri Slaby,
	Andreas Mohr, Tetsuo Handa, Linux Kernel Mailing List

Hello,

On (08/29/17 10:00), Linus Torvalds wrote:
> On Tue, Aug 29, 2017 at 6:40 AM, Sergey Senozhatsky
> <sergey.senozhatsky.work@gmail.com> wrote:
> > Pavel reported that
> >         printk("foo"); printk("bar");
> >
> > now does not produce a single continuation "foobar" line, but
> > instead produces two lines
> >                 foo
> >                 bar
> 
> And that's the *correct* behavior.

ok. thanks for taking a look.

> Stop trying to fix that. Fix the printk's instead.
> 
> In particular, the
> 
>     printk("bar");
> 
> could have come from an interrupt, and have nothing what-so-ever to do
> with "foo".
> 
> If you want continuations, you
> 
>  (a) make sure the first one doesn't end in a newline
> 
>  (b) make sure the second printk has a KERN_CONT
> 
>  (c) even after that, ask yourself how much you _really_ want
> continuations, because there are going to be situations where it still
> doesn't work.

yes, continuations are not really welcomed. I thought that this
particular case could be considered a regression. but your position
is pretty clear.

> I refuse to help those things. We mis-designed things, and the
> continuations were a mistake to begin with, but they were a mistake
> that was understandable in the timeframe they happened. But it's not
> something we should support, and it's most definitely is not something
> we should then say "oh, you were broken shit that didn't even bother
> to add the KERN_CONT, let me help your crap".
> 
> No.
> 
> Only acceptable use of continuations is basically boot-time testing,
> when you do things like
> 
>      printk("Testing feature XYZ..");
>      this_may_blow_up_because_of_hw_bugs();
>      printk(KERN_CONT " ... ok\n");
>
> and anything else you should seriously try to marshal the data
> *before* doing a printk(), and not expect printk() to marshal it for
> you.

ok. that's something several people asked for -- some sort of buffered
printk mode; but people don't want to use a buffer allocated on the stack
(or kmalloc-ed, etc.) to do sprintf() on it and then feed it to printk("%s"),
because this adds some extra cost:

	void foo(void)
	{
		char cont_string[256];
		size_t sz;

		sz = sprintf(cont_string + sz, "%xxxx", data1...);
		do_abc()
		sz += sprintf(cont_string + sz, "%xxxx", data1...);

		....

		printk("%s\n", cont_string)   // does "sprintf" again
					      // and then memcpy
	}


I thought about re-using printk-safe per-CPU buffers for that purpose.
this saves us memory, because printk-safe buffers are always there, but
it has some disadvantages. namely, to use printk-safe buffer we need to
disable local interrupts. so something like this

	printk_buffered_mode_begin();   // disables local irq

	printk()	// appends data to the per-CPU buffer
	printk()
	printk()

	printk_buffered_mode_end();  // append messages to consequent logbuf
				     // entries
				     // enable local irqs.

... not sure, how usable this will end up to be.
probably not usable at all.

> But for legacy reasons, we do end up trying to support KERN_CONT.
> Just barely.
> 
> I'd really like to get rid of it entirely, because the whole log-based
> structure really really doesn't work well for it (what if somebody has
> already read the partial line from the logs?)
> 
> Our printk stuff didn't used to be log-based. It was just a plain
> character-based circular buffer. Back then that KERN_CONT made a whole
> lot more sense.

	-ss

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-08-29 17:33         ` Joe Perches
@ 2017-08-29 17:36           ` Linus Torvalds
  2017-08-29 17:48             ` Joe Perches
  0 siblings, 1 reply; 94+ messages in thread
From: Linus Torvalds @ 2017-08-29 17:36 UTC (permalink / raw)
  To: Joe Perches
  Cc: Pavel Machek, Sergey Senozhatsky, Petr Mladek, Steven Rostedt,
	Jan Kara, Andrew Morton, Jiri Slaby, Andreas Mohr, Tetsuo Handa,
	Linux Kernel Mailing List, Sergey Senozhatsky

On Tue, Aug 29, 2017 at 10:33 AM, Joe Perches <joe@perches.com> wrote:
>
> Your change broke a bunch of output.

Tough. We've done that before to force people to fix their code.

I'm actually upset that EVEN NOW (and it's been, what, 18 months),
people ask for the old broken shit behavior back.

It's ten years since we introduced the marker, and it's been over a
year since I made that pretty much a requirement, and people still
want to do the broken crap.

I'm not AT ALL feeling sorry for people. Fix your shit, or see ugly
output. Those are the two choices.

          Linus

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-08-29 17:36           ` Linus Torvalds
@ 2017-08-29 17:48             ` Joe Perches
  0 siblings, 0 replies; 94+ messages in thread
From: Joe Perches @ 2017-08-29 17:48 UTC (permalink / raw)
  To: Linus Torvalds
  Cc: Pavel Machek, Sergey Senozhatsky, Petr Mladek, Steven Rostedt,
	Jan Kara, Andrew Morton, Jiri Slaby, Andreas Mohr, Tetsuo Handa,
	Linux Kernel Mailing List, Sergey Senozhatsky

On Tue, 2017-08-29 at 10:36 -0700, Linus Torvalds wrote:
> On Tue, Aug 29, 2017 at 10:33 AM, Joe Perches <joe@perches.com> wrote:
> > 
> > Your change broke a bunch of output.
> 
> Tough. We've done that before to force people to fix their code.

No worries.
I don't mind the change at all really.

You do seem to like enhancing your reputation against
"plays well with others" kindergarten grading.

> I'm actually upset that EVEN NOW (and it's been, what, 18 months),

Odd maths.
October 2016 to August 2017 is barely half that.

> people ask for the old broken shit behavior back.

You seem to overestimate how often people test their
code against current kernels.

And look for documentation that shows this as a
requirement.

Other than your commit log entry and some LKML chatter
I believe that you'll have a hard time finding any.

$ git grep -i KERN_CONT Documentation/
$ git grep -i pr_cont Documentation/
$

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-08-29 17:33             ` Sergey Senozhatsky
@ 2017-08-29 17:52               ` Linus Torvalds
  2017-08-29 18:09                 ` Joe Perches
  2017-08-30  0:58                 ` Sergey Senozhatsky
  0 siblings, 2 replies; 94+ messages in thread
From: Linus Torvalds @ 2017-08-29 17:52 UTC (permalink / raw)
  To: Sergey Senozhatsky
  Cc: Sergey Senozhatsky, Pavel Machek, Petr Mladek, Steven Rostedt,
	Jan Kara, Andrew Morton, Jiri Slaby, Andreas Mohr, Tetsuo Handa,
	Linux Kernel Mailing List

On Tue, Aug 29, 2017 at 10:33 AM, Sergey Senozhatsky
<sergey.senozhatsky@gmail.com> wrote:
>
> ok. that's something several people asked for -- some sort of buffered
> printk mode; but people don't want to use a buffer allocated on the stack
> (or kmalloc-ed, etc.) to do sprintf() on it and then feed it to printk("%s"),
> because this adds some extra cost:

I don't like the notion of per-cpu buffers either, because then you
suddenly get atomicity issues, and you really don't want that.

My preference as a user is actually to just have a dynamically
re-sizable buffer (that's pretty much what I've done in *every* single
user space project I've had in the last decade), but because some
users might have atomicity issues I do suspect that we should just use
a stack buffer.

And then perhaps say that the buffer size has to be capped at 80 characters.

Because if you're printing more than 80 characters and expecting it
all to fit on a line, you're doing something else wrong anyway.

And hide it not as a explicit "char buffer[80]]" allocation, but as a
"struct line_buffer" or similar, so that

 (a) people don't get the line size wrong

 (b) the buffering code can add a few fields for length etc in there too

Introduce a few helper functions for it:

 init_line_buffer(&buf);
 print_line(&buf, fmt, args);
 vprint_line(&buf, fmt, vararg);
 finish_line(&buf);

or whatever, and it sounds like it should be pretty easy to use.

                Linus

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-08-29 17:52               ` Linus Torvalds
@ 2017-08-29 18:09                 ` Joe Perches
  2017-08-30  1:07                   ` Sergey Senozhatsky
  2017-08-30  0:58                 ` Sergey Senozhatsky
  1 sibling, 1 reply; 94+ messages in thread
From: Joe Perches @ 2017-08-29 18:09 UTC (permalink / raw)
  To: Linus Torvalds, Sergey Senozhatsky, Tejun Heo
  Cc: Sergey Senozhatsky, Pavel Machek, Petr Mladek, Steven Rostedt,
	Jan Kara, Andrew Morton, Jiri Slaby, Andreas Mohr, Tetsuo Handa,
	Linux Kernel Mailing List

On Tue, 2017-08-29 at 10:52 -0700, Linus Torvalds wrote:
> On Tue, Aug 29, 2017 at 10:33 AM, Sergey Senozhatsky
> <sergey.senozhatsky@gmail.com> wrote:
> > 
> > ok. that's something several people asked for -- some sort of buffered
> > printk mode; but people don't want to use a buffer allocated on the stack
> > (or kmalloc-ed, etc.) to do sprintf() on it and then feed it to printk("%s"),
> > because this adds some extra cost:
> 
> I don't like the notion of per-cpu buffers either, because then you
> suddenly get atomicity issues, and you really don't want that.
> 
> My preference as a user is actually to just have a dynamically
> re-sizable buffer (that's pretty much what I've done in *every* single
> user space project I've had in the last decade), but because some
> users might have atomicity issues I do suspect that we should just use
> a stack buffer.
> 
> And then perhaps say that the buffer size has to be capped at 80 characters.
> 
> Because if you're printing more than 80 characters and expecting it
> all to fit on a line, you're doing something else wrong anyway.
> 
> And hide it not as a explicit "char buffer[80]]" allocation, but as a
> "struct line_buffer" or similar, so that
> 
>  (a) people don't get the line size wrong
> 
>  (b) the buffering code can add a few fields for length etc in there too
> 
> Introduce a few helper functions for it:
> 
>  init_line_buffer(&buf);
>  print_line(&buf, fmt, args);
>  vprint_line(&buf, fmt, vararg);
>  finish_line(&buf);
> 
> or whatever, and it sounds like it should be pretty easy to use.

Mostly true and not a new solution.

You'll now need to add &buf to called functions that
continue individual line output.

Tejun Heo suggested the very similar mprintk back in 2008.

http://thread.gmane.org/gmane.linux.ide/27199

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-08-29 16:48   ` Linus Torvalds
  2017-08-29 17:10     ` Joe Perches
@ 2017-08-29 20:24     ` Pavel Machek
  2017-09-01  1:40       ` Sergey Senozhatsky
  1 sibling, 1 reply; 94+ messages in thread
From: Pavel Machek @ 2017-08-29 20:24 UTC (permalink / raw)
  To: Linus Torvalds
  Cc: Sergey Senozhatsky, Petr Mladek, Steven Rostedt, Jan Kara,
	Andrew Morton, Jiri Slaby, Andreas Mohr, Tetsuo Handa,
	Linux Kernel Mailing List, Sergey Senozhatsky

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

Hi!

> > In 4.13-rc, printk("foo"); printk("bar"); seems to produce
> > foo\nbar. That's... quite surprising/unwelcome. What is going on
> > there? Are timestamps responsible?
> 
> No.
> 
> It's actively trying to treach you not to do shit.
> 
> If you want to continue a line, you NEED to use KERN_CONT.
> 
> That has always been true. It hasn't always been enforced, though.

Dumping hex buffer for debugging should not be a rocket science. You
are welcome not add checkpatch rules to prevent such code from being
merged...

> Stop doing continuations at all please. But if you do, you'd better
> use KERN_CONT. And if you don't, and you get multiple lines, it's your
> own damn fault.

..but please don't make debugging harder than it already is. Just
because you spend too much time doing kernel does not mean that
everyone is; having to remember "this is kernel, so it has to be
special, you have to do printk, not printf" is bad enough, having
different semantics is even more ugly.

Thanks,

									Pavel
-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 181 bytes --]

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-08-29 17:12             ` Linus Torvalds
@ 2017-08-29 20:41               ` Tetsuo Handa
  2017-08-29 20:51                 ` Linus Torvalds
  2017-08-29 23:50               ` Steven Rostedt
  1 sibling, 1 reply; 94+ messages in thread
From: Tetsuo Handa @ 2017-08-29 20:41 UTC (permalink / raw)
  To: torvalds, sergey.senozhatsky.work
  Cc: pavel, sergey.senozhatsky, pmladek, rostedt, jack, akpm, jslaby,
	andi, linux-kernel

Linus Torvalds wrote:
> On Tue, Aug 29, 2017 at 10:00 AM, Linus Torvalds
> <torvalds@linux-foundation.org> wrote:
> >
> > I refuse to help those things. We mis-designed things
> 
> Actually, let me rephrase that:
> 
> It might actually be a good idea to help those things, by making
> helper functions available that do the marshalling.
> 
> So not calling "printk()" directly, but having a set of simple
> "buffer_print()" functions where each user has its own buffer, and
> then the "buffer_print()" functions will help people do nicely output
> data.
> 
> So if the issue is that people want to print (for example) hex dumps
> one character at a time, but don't want to have each character show up
> on a line of their own, I think we might well add a few functions to
> help dop that.
> 
> But they wouldn't be "printk". They would be the buffering functions
> that then call printk when tyhey have buffered a line.
> 
> That avoids the whole nasty issue with printk - printk wants to show
> stuff early (because _maybe_ it's critical) and printk wants to make
> log records with timestamps and loglevels. And printk has serious
> locking issues that are really nasty and fundamental.
> 
> A private buffer has none of those issues.

Yes, I posted "[PATCH] printk: Add best-effort printk() buffering." at
http://lkml.kernel.org/r/1493560477-3016-1-git-send-email-penguin-kernel@I-love.SAKURA.ne.jp .

> 
>                  Linus
> 

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-08-29 20:41               ` Tetsuo Handa
@ 2017-08-29 20:51                 ` Linus Torvalds
  2017-09-02  6:12                   ` Tetsuo Handa
  0 siblings, 1 reply; 94+ messages in thread
From: Linus Torvalds @ 2017-08-29 20:51 UTC (permalink / raw)
  To: Tetsuo Handa
  Cc: Sergey Senozhatsky, Pavel Machek, SergeySenozhatsky, Petr Mladek,
	Steven Rostedt, Jan Kara, Andrew Morton, Jiri Slaby,
	Andreas Mohr, Linux Kernel Mailing List

On Tue, Aug 29, 2017 at 1:41 PM, Tetsuo Handa
<penguin-kernel@i-love.sakura.ne.jp> wrote:
>>
>> A private buffer has none of those issues.
>
> Yes, I posted "[PATCH] printk: Add best-effort printk() buffering." at
> http://lkml.kernel.org/r/1493560477-3016-1-git-send-email-penguin-kernel@I-love.SAKURA.ne.jp .

No, this is exactly what I *don't* want, because it takes over printk() itself.

And that's problematic, because nesting happens for various reasons.

For example, you try to handle that nesting with printk_context(), and
nothing when an interrupt happens.

But that is fundamentally broken.

Just to give an example: what if an interrupt happens, it does this
buffering thing, then it gets interrupted by *another* interrupt, and
now the printk from that other interrupt gets incorrectly nested
together with the first one, because your "printk_context()" gives
them the same context?

And it really doesn't have to even be interrupts. Look at what happens
if you take a page fault in kernel space. Same exact deal. Both are
sleeping contexts.

So I really think that the only thing that knows what the "context" is
is the person who does the printing. So if you want to create a
printing buffer, it should be explicit. You allocate the buffer ahead
of time (perhaps on the stack, possibly using actual allocations), and
you use that explicit context.

Yes, it means that you don't do "printk()". You do an actual
"buf_print()" or similar.

             Linus

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-08-29 17:12             ` Linus Torvalds
  2017-08-29 20:41               ` Tetsuo Handa
@ 2017-08-29 23:50               ` Steven Rostedt
  2017-08-29 23:59                 ` Linus Torvalds
  2017-08-30  1:03                 ` Sergey Senozhatsky
  1 sibling, 2 replies; 94+ messages in thread
From: Steven Rostedt @ 2017-08-29 23:50 UTC (permalink / raw)
  To: Linus Torvalds
  Cc: Sergey Senozhatsky, Pavel Machek, Sergey Senozhatsky,
	Petr Mladek, Jan Kara, Andrew Morton, Jiri Slaby, Andreas Mohr,
	Tetsuo Handa, Linux Kernel Mailing List

On Tue, 29 Aug 2017 10:12:22 -0700
Linus Torvalds <torvalds@linux-foundation.org> wrote:

> On Tue, Aug 29, 2017 at 10:00 AM, Linus Torvalds
> <torvalds@linux-foundation.org> wrote:
> >
> > I refuse to help those things. We mis-designed things  
> 
> Actually, let me rephrase that:
> 
> It might actually be a good idea to help those things, by making
> helper functions available that do the marshalling.
> 
> So not calling "printk()" directly, but having a set of simple
> "buffer_print()" functions where each user has its own buffer, and
> then the "buffer_print()" functions will help people do nicely output
> data.
> 
> So if the issue is that people want to print (for example) hex dumps
> one character at a time, but don't want to have each character show up
> on a line of their own, I think we might well add a few functions to
> help dop that.
> 
> But they wouldn't be "printk". They would be the buffering functions
> that then call printk when tyhey have buffered a line.
> 
> That avoids the whole nasty issue with printk - printk wants to show
> stuff early (because _maybe_ it's critical) and printk wants to make
> log records with timestamps and loglevels. And printk has serious
> locking issues that are really nasty and fundamental.
> 
> A private buffer has none of those issues.

What about using the seq_buf*() then?

	struct seq_buf s;

	buf = kmalloc(mysize);
	seq_buf_init(&s, buf, mysize);

	seq_printf(&s,"blah blah %d", bah_blah);
	[...]
	seq_printf(&s, "my last print\n");

	printk("%.*s", s.len, s.buffer);

	kfree(buf);

This is what the NMI "safe" printks basically do.

-- Steve

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-08-29 23:50               ` Steven Rostedt
@ 2017-08-29 23:59                 ` Linus Torvalds
  2017-08-30  1:03                 ` Sergey Senozhatsky
  1 sibling, 0 replies; 94+ messages in thread
From: Linus Torvalds @ 2017-08-29 23:59 UTC (permalink / raw)
  To: Steven Rostedt
  Cc: Sergey Senozhatsky, Pavel Machek, Sergey Senozhatsky,
	Petr Mladek, Jan Kara, Andrew Morton, Jiri Slaby, Andreas Mohr,
	Tetsuo Handa, Linux Kernel Mailing List

On Tue, Aug 29, 2017 at 4:50 PM, Steven Rostedt <rostedt@goodmis.org> wrote:
>
> What about using the seq_buf*() then?

They do have the nice property that because we use them for various
/proc files, there are some helper functions in addition to just the
puts/printt/vprintf.

Ie seq_buf_putmem_hex().

And yeah, you can just do

        char buffer[80];
        struct seq_buf s;

        seq_buf_init(&s, buffer, sizeof(buffer));

if you want to use a stack buffer for a single line.

          Linus

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-08-29 17:52               ` Linus Torvalds
  2017-08-29 18:09                 ` Joe Perches
@ 2017-08-30  0:58                 ` Sergey Senozhatsky
  1 sibling, 0 replies; 94+ messages in thread
From: Sergey Senozhatsky @ 2017-08-30  0:58 UTC (permalink / raw)
  To: Linus Torvalds
  Cc: Sergey Senozhatsky, Sergey Senozhatsky, Pavel Machek,
	Petr Mladek, Steven Rostedt, Jan Kara, Andrew Morton, Jiri Slaby,
	Andreas Mohr, Tetsuo Handa, Linux Kernel Mailing List

Hello,

On (08/29/17 10:52), Linus Torvalds wrote:
> On Tue, Aug 29, 2017 at 10:33 AM, Sergey Senozhatsky
> <sergey.senozhatsky@gmail.com> wrote:
> >
> > ok. that's something several people asked for -- some sort of buffered
> > printk mode; but people don't want to use a buffer allocated on the stack
> > (or kmalloc-ed, etc.) to do sprintf() on it and then feed it to printk("%s"),
> > because this adds some extra cost:
> 
[..]
> Introduce a few helper functions for it:
> 
>  init_line_buffer(&buf);
>  print_line(&buf, fmt, args);
>  vprint_line(&buf, fmt, vararg);
>  finish_line(&buf);
> 
> or whatever, and it sounds like it should be pretty easy to use.

ok, I was short on details (sorry, it was almost 3am).

what I was talking/thinking about is not just a single complete continuation
line, but a whole bunch of printk calls (including continuation lines). like
OOM report with backtraces, and so on. the problem people are having (well,
according to emails I have got in my inbox) is the fact that
	printk("a"); printk("b");
	
can appear in the logbuf (and serial console) pretty far; no one knows what
can happen between those calls. so the buffered-printk buffer is supposed to
be big enough for N lines and, more importantly, it stores those lines in
logbuf in consequent entries.

so the difference here is

	while (buffer->whatever)
		printk("%s\n", buffer->msg[i]);

vs

	spin_lock(&logbuf_lock);
	while (buffer->whatever)
		log_store(buffer->msg[i]);
	spin_unlock(&logbuf_lock);


a dynamic buffer with resizing probably may not work good enough in some
OOM cases.

	-ss

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-08-29 23:50               ` Steven Rostedt
  2017-08-29 23:59                 ` Linus Torvalds
@ 2017-08-30  1:03                 ` Sergey Senozhatsky
  2017-08-30  1:10                   ` Steven Rostedt
  1 sibling, 1 reply; 94+ messages in thread
From: Sergey Senozhatsky @ 2017-08-30  1:03 UTC (permalink / raw)
  To: Steven Rostedt
  Cc: Linus Torvalds, Sergey Senozhatsky, Pavel Machek,
	Sergey Senozhatsky, Petr Mladek, Jan Kara, Andrew Morton,
	Jiri Slaby, Andreas Mohr, Tetsuo Handa,
	Linux Kernel Mailing List

Hello,

On (08/29/17 19:50), Steven Rostedt wrote:
[..]
> > A private buffer has none of those issues.
> 
> What about using the seq_buf*() then?
> 
> 	struct seq_buf s;
> 
> 	buf = kmalloc(mysize);
> 	seq_buf_init(&s, buf, mysize);
> 
> 	seq_printf(&s,"blah blah %d", bah_blah);
> 	[...]
> 	seq_printf(&s, "my last print\n");
> 
> 	printk("%.*s", s.len, s.buffer);
> 
> 	kfree(buf);

could do. for a single continuation line printk("%.*s", s.len, s.buffer)
this will work perfectly fine. for a more general case - backtraces, dumps,
etc. - this requires some tweaks.

	-ss

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-08-29 18:09                 ` Joe Perches
@ 2017-08-30  1:07                   ` Sergey Senozhatsky
  0 siblings, 0 replies; 94+ messages in thread
From: Sergey Senozhatsky @ 2017-08-30  1:07 UTC (permalink / raw)
  To: Joe Perches
  Cc: Linus Torvalds, Sergey Senozhatsky, Tejun Heo,
	Sergey Senozhatsky, Pavel Machek, Petr Mladek, Steven Rostedt,
	Jan Kara, Andrew Morton, Jiri Slaby, Andreas Mohr, Tetsuo Handa,
	Linux Kernel Mailing List

On (08/29/17 11:09), Joe Perches wrote:
[..]
> > Introduce a few helper functions for it:
> > 
> >  init_line_buffer(&buf);
> >  print_line(&buf, fmt, args);
> >  vprint_line(&buf, fmt, vararg);
> >  finish_line(&buf);
> > 
> > or whatever, and it sounds like it should be pretty easy to use.
> 
> Mostly true and not a new solution.
> 
> You'll now need to add &buf to called functions that
> continue individual line output.
> 
> Tejun Heo suggested the very similar mprintk back in 2008.
> 
> http://thread.gmane.org/gmane.linux.ide/27199

interesting. thanks for the link.

	-ss

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-08-30  1:03                 ` Sergey Senozhatsky
@ 2017-08-30  1:10                   ` Steven Rostedt
  2017-08-30  1:51                     ` Sergey Senozhatsky
                                       ` (2 more replies)
  0 siblings, 3 replies; 94+ messages in thread
From: Steven Rostedt @ 2017-08-30  1:10 UTC (permalink / raw)
  To: Sergey Senozhatsky
  Cc: Linus Torvalds, Pavel Machek, Sergey Senozhatsky, Petr Mladek,
	Jan Kara, Andrew Morton, Jiri Slaby, Andreas Mohr, Tetsuo Handa,
	Linux Kernel Mailing List

On Wed, 30 Aug 2017 10:03:48 +0900
Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> wrote:

> Hello,
> 
> On (08/29/17 19:50), Steven Rostedt wrote:
> [..]
> > > A private buffer has none of those issues.  
> > 
> > What about using the seq_buf*() then?
> > 
> > 	struct seq_buf s;
> > 
> > 	buf = kmalloc(mysize);
> > 	seq_buf_init(&s, buf, mysize);
> > 
> > 	seq_printf(&s,"blah blah %d", bah_blah);
> > 	[...]
> > 	seq_printf(&s, "my last print\n");
> > 
> > 	printk("%.*s", s.len, s.buffer);
> > 
> > 	kfree(buf);  
> 
> could do. for a single continuation line printk("%.*s", s.len, s.buffer)
> this will work perfectly fine. for a more general case - backtraces, dumps,
> etc. - this requires some tweaks.

We could simply add a seq_buf_printk() that is implemented in the printk
proper, to parse the seq_buf buffer properly, and add the timestamps and
such.

-- Steve

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-08-30  1:10                   ` Steven Rostedt
@ 2017-08-30  1:51                     ` Sergey Senozhatsky
  2017-08-30  1:52                     ` Joe Perches
  2017-09-01 13:19                     ` Sergey Senozhatsky
  2 siblings, 0 replies; 94+ messages in thread
From: Sergey Senozhatsky @ 2017-08-30  1:51 UTC (permalink / raw)
  To: Steven Rostedt
  Cc: Sergey Senozhatsky, Linus Torvalds, Pavel Machek,
	Sergey Senozhatsky, Petr Mladek, Jan Kara, Andrew Morton,
	Jiri Slaby, Andreas Mohr, Tetsuo Handa,
	Linux Kernel Mailing List

On (08/29/17 21:10), Steven Rostedt wrote:
> > On (08/29/17 19:50), Steven Rostedt wrote:
> > [..]
> > > > A private buffer has none of those issues.  
> > > 
> > > What about using the seq_buf*() then?
> > > 
> > > 	struct seq_buf s;
> > > 
> > > 	buf = kmalloc(mysize);
> > > 	seq_buf_init(&s, buf, mysize);
> > > 
> > > 	seq_printf(&s,"blah blah %d", bah_blah);
> > > 	[...]
> > > 	seq_printf(&s, "my last print\n");
> > > 
> > > 	printk("%.*s", s.len, s.buffer);
> > > 
> > > 	kfree(buf);  
> > 
> > could do. for a single continuation line printk("%.*s", s.len, s.buffer)
> > this will work perfectly fine. for a more general case - backtraces, dumps,
> > etc. - this requires some tweaks.
> 
> We could simply add a seq_buf_printk() that is implemented in the printk
> proper, to parse the seq_buf buffer properly, and add the timestamps and
> such.

sounds like a plan :)

	-ss

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-08-30  1:10                   ` Steven Rostedt
  2017-08-30  1:51                     ` Sergey Senozhatsky
@ 2017-08-30  1:52                     ` Joe Perches
  2017-08-30  2:25                       ` Sergey Senozhatsky
  2017-09-01 13:19                     ` Sergey Senozhatsky
  2 siblings, 1 reply; 94+ messages in thread
From: Joe Perches @ 2017-08-30  1:52 UTC (permalink / raw)
  To: Steven Rostedt, Sergey Senozhatsky
  Cc: Linus Torvalds, Pavel Machek, Sergey Senozhatsky, Petr Mladek,
	Jan Kara, Andrew Morton, Jiri Slaby, Andreas Mohr, Tetsuo Handa,
	Linux Kernel Mailing List

On Tue, 2017-08-29 at 21:10 -0400, Steven Rostedt wrote:
> On Wed, 30 Aug 2017 10:03:48 +0900
> Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> wrote:
> 
> > Hello,
> > 
> > On (08/29/17 19:50), Steven Rostedt wrote:
> > [..]
> > > > A private buffer has none of those issues.  
> > > 
> > > What about using the seq_buf*() then?
> > > 
> > > 	struct seq_buf s;
> > > 
> > > 	buf = kmalloc(mysize);
> > > 	seq_buf_init(&s, buf, mysize);
> > > 
> > > 	seq_printf(&s,"blah blah %d", bah_blah);
> > > 	[...]
> > > 	seq_printf(&s, "my last print\n");
> > > 
> > > 	printk("%.*s", s.len, s.buffer);
> > > 
> > > 	kfree(buf);  
> > 
> > could do. for a single continuation line printk("%.*s", s.len, s.buffer)
> > this will work perfectly fine. for a more general case - backtraces, dumps,
> > etc. - this requires some tweaks.
> 
> We could simply add a seq_buf_printk() that is implemented in the printk
> proper, to parse the seq_buf buffer properly, and add the timestamps and
> such.

No need.  printk would already add timestamps.

One addition might be to add a bit to initialize
the buffer so that printk("%s", s->buffer) is simpler.
---
diff --git a/include/linux/seq_buf.h b/include/linux/seq_buf.h
index fb7eb9ccb1cd..fb6c9de0ee33 100644
--- a/include/linux/seq_buf.h
+++ b/include/linux/seq_buf.h
@@ -26,6 +26,7 @@ static inline void seq_buf_clear(struct seq_buf *s)
 {
 	s->len = 0;
 	s->readpos = 0;
+	*s->buffer = 0;
 }
 
 static inline void

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-08-30  1:52                     ` Joe Perches
@ 2017-08-30  2:25                       ` Sergey Senozhatsky
  2017-08-30  2:31                         ` Joe Perches
  0 siblings, 1 reply; 94+ messages in thread
From: Sergey Senozhatsky @ 2017-08-30  2:25 UTC (permalink / raw)
  To: Joe Perches
  Cc: Steven Rostedt, Sergey Senozhatsky, Linus Torvalds, Pavel Machek,
	Sergey Senozhatsky, Petr Mladek, Jan Kara, Andrew Morton,
	Jiri Slaby, Andreas Mohr, Tetsuo Handa,
	Linux Kernel Mailing List

On (08/29/17 18:52), Joe Perches wrote:
[..]
> > We could simply add a seq_buf_printk() that is implemented in the printk
> > proper, to parse the seq_buf buffer properly, and add the timestamps and
> > such.
> 
> No need.  printk would already add timestamps.

the idea is not to do printk() on that seq buffer at all, but to
log_store(), atomically, seq buffer messages

	spin_lock(&logbuf_lock)
	while (offset < seq_buffer->len) {
		...
		log_store(seq->buffer + offset);
		...
	}
	spin_unlock(&logbuf_unlock)

	-ss

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-08-30  2:25                       ` Sergey Senozhatsky
@ 2017-08-30  2:31                         ` Joe Perches
  2017-08-30  2:47                           ` Sergey Senozhatsky
  0 siblings, 1 reply; 94+ messages in thread
From: Joe Perches @ 2017-08-30  2:31 UTC (permalink / raw)
  To: Sergey Senozhatsky
  Cc: Steven Rostedt, Linus Torvalds, Pavel Machek, Sergey Senozhatsky,
	Petr Mladek, Jan Kara, Andrew Morton, Jiri Slaby, Andreas Mohr,
	Tetsuo Handa, Linux Kernel Mailing List

On Wed, 2017-08-30 at 11:25 +0900, Sergey Senozhatsky wrote:
> On (08/29/17 18:52), Joe Perches wrote:
> [..]
> > > We could simply add a seq_buf_printk() that is implemented in the printk
> > > proper, to parse the seq_buf buffer properly, and add the timestamps and
> > > such.
> > 
> > No need.  printk would already add timestamps.
> 
> the idea is not to do printk() on that seq buffer at all, but to
> log_store(), atomically, seq buffer messages
> 
> 	spin_lock(&logbuf_lock)
> 	while (offset < seq_buffer->len) {
> 		...
> 		log_store(seq->buffer + offset);
> 		...
> 	}
> 	spin_unlock(&logbuf_unlock)

Why?

What's wrong with a simple printk?
It'd still do a log_store.

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-08-30  2:31                         ` Joe Perches
@ 2017-08-30  2:47                           ` Sergey Senozhatsky
  2017-08-30  2:58                             ` Joe Perches
  2017-09-05  9:44                             ` Petr Mladek
  0 siblings, 2 replies; 94+ messages in thread
From: Sergey Senozhatsky @ 2017-08-30  2:47 UTC (permalink / raw)
  To: Joe Perches
  Cc: Sergey Senozhatsky, Steven Rostedt, Linus Torvalds, Pavel Machek,
	Sergey Senozhatsky, Petr Mladek, Jan Kara, Andrew Morton,
	Jiri Slaby, Andreas Mohr, Tetsuo Handa,
	Linux Kernel Mailing List

On (08/29/17 19:31), Joe Perches wrote:
[..]
> > the idea is not to do printk() on that seq buffer at all, but to
> > log_store(), atomically, seq buffer messages
> > 
> > 	spin_lock(&logbuf_lock)
> > 	while (offset < seq_buffer->len) {
> > 		...
> > 		log_store(seq->buffer + offset);
> > 		...
> > 	}
> > 	spin_unlock(&logbuf_unlock)
> 
> Why?
> 
> What's wrong with a simple printk?
> It'd still do a log_store.

sure, it will. but in separate logbuf entries, and between two
consequent printk calls on the same CPU a lot of stuff can happen:
IRQs->printks, rescheduling->printks, etc. etc. (not to mention
concurrent printks from other CPUs) so what people want to have is
to have a way to make several printks appear next to each other in
the logs (dmesg or serial log). Tetsuo wants this, for instance,
for OOM reports and backtraces. SCIS/ATA people want it as well.

	-ss

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-08-30  2:47                           ` Sergey Senozhatsky
@ 2017-08-30  2:58                             ` Joe Perches
  2017-08-30  5:37                               ` Sergey Senozhatsky
  2017-09-05  9:44                             ` Petr Mladek
  1 sibling, 1 reply; 94+ messages in thread
From: Joe Perches @ 2017-08-30  2:58 UTC (permalink / raw)
  To: Sergey Senozhatsky
  Cc: Steven Rostedt, Linus Torvalds, Pavel Machek, Sergey Senozhatsky,
	Petr Mladek, Jan Kara, Andrew Morton, Jiri Slaby, Andreas Mohr,
	Tetsuo Handa, Linux Kernel Mailing List

On Wed, 2017-08-30 at 11:47 +0900, Sergey Senozhatsky wrote:
> On (08/29/17 19:31), Joe Perches wrote:
> [..]
> > > the idea is not to do printk() on that seq buffer at all, but to
> > > log_store(), atomically, seq buffer messages
> > > 
> > > 	spin_lock(&logbuf_lock)
> > > 	while (offset < seq_buffer->len) {
> > > 		...
> > > 		log_store(seq->buffer + offset);
> > > 		...
> > > 	}
> > > 	spin_unlock(&logbuf_unlock)
> > 
> > Why?
> > 
> > What's wrong with a simple printk?
> > It'd still do a log_store.
> 
> sure, it will. but in separate logbuf entries, and between two
> consequent printk calls on the same CPU a lot of stuff can happen:

I think you don't quite understand how this would work.
The idea is that the entire concatenated bit would be emitted
in one go.

One use case already in place with seq_buf_init is in
drivers/clk/tegra/clk-bpmp.c

Basically, it's

    static void tegra_bpmp_clk_info_dump(struct tegra_bpmp *bpmp,
    	    	    	    	         const char *level,
    	    	    	    	         const struct tegra_bpmp_clk_info *info)
    {
    	    const char *prefix = "";
    	    struct seq_buf buf;
    	    unsigned int i;
    	    char flags[64];

    	    seq_buf_init(&buf, flags, sizeof(flags));

    	    if (info->flags)
    	    	    seq_buf_printf(&buf, "(");

    	    if (info->flags & TEGRA_BPMP_CLK_HAS_MUX) {
    	    	    seq_buf_printf(&buf, "%smux", prefix);
    	    	    prefix = ", ";
    	    }

    	    if ((info->flags & TEGRA_BPMP_CLK_HAS_SET_RATE) == 0) {
    	    	    seq_buf_printf(&buf, "%sfixed", prefix);
    	    	    prefix = ", ";
    	    }

    	    if (info->flags & TEGRA_BPMP_CLK_IS_ROOT) {
    	    	    seq_buf_printf(&buf, "%sroot", prefix);
    	    	    prefix = ", ";
    	    }

    	    if (info->flags)
    	    	    seq_buf_printf(&buf, ")");

    	    [...]
    	    dev_printk(level, bpmp->dev, "  flags: %lx %s\n", info->flags, flags);

so that the dev_printk is simply emitting a buffer from
concatenated strings via the seq_buf_printf uses.

The other use case would be an entire printk buffer
all at once.

ala:

	seq_buf_init(seq, buf, sizeof(buf));
	seq_buf_printf(&buf, "KERN_<LEVEL> fmt...", args...)
	for (i = 0; i < bar; i++)
		seq_buf_printf(&buf, fmt, ...)
	seq_buf_printk(&buf);

or:

	seq_buf_init(seq, buf, sizeof(buf));
	seq_buf_printf(&buf,
fmt, args...)
	for (i = 0; i < bar; i++)
		seq_buf_printf(&bu
f, fmt, args...)
	seq_buf_printk(&buf, KERN_<LEVEL>);

I can't think of another use case.

Can you?

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-08-30  2:58                             ` Joe Perches
@ 2017-08-30  5:37                               ` Sergey Senozhatsky
  2017-09-08 10:18                                 ` Pavel Machek
  0 siblings, 1 reply; 94+ messages in thread
From: Sergey Senozhatsky @ 2017-08-30  5:37 UTC (permalink / raw)
  To: Joe Perches
  Cc: Sergey Senozhatsky, Steven Rostedt, Linus Torvalds, Pavel Machek,
	Sergey Senozhatsky, Petr Mladek, Jan Kara, Andrew Morton,
	Jiri Slaby, Andreas Mohr, Tetsuo Handa,
	Linux Kernel Mailing List

On (08/29/17 19:58), Joe Perches wrote:
> > > 
> > > Why?
> > > 
> > > What's wrong with a simple printk?
> > > It'd still do a log_store.
> > 
> > sure, it will. but in separate logbuf entries, and between two
> > consequent printk calls on the same CPU a lot of stuff can happen:
> 
> I think you don't quite understand how this would work.
> The idea is that the entire concatenated bit would be emitted
> in one go.

may be :)

I was thinking about the way to make it work in similar way with
printk-safe/printk-nmi. basically seq buffer should hold both
continuation and "normal" lines, IMHO. when we emit the buffer
we do something like this

	/* Print line by line. */
	while (c < end) {
		if (*c == '\n') {
			printk_safe_flush_line(start, c - start + 1);
			start = ++c;
			header = true;
			continue;
		}

		/* Handle continuous lines or missing new line. */
		if ((c + 1 < end) && printk_get_level(c)) {
			if (header) {
				c = printk_skip_level(c);
				continue;
			}

			printk_safe_flush_line(start, c - start);
			start = c++;
			header = true;
			continue;
		}

		header = false;
		c++;
	}

except that instead of printk_safe_flush_line() we will call log_store()
and the whole loop will be under logbuf_lock.

for that to work, we need API to require header/loglevel etc for every
message. so the use case can look like this:

	init_printk_buffer(&buf);
	print_line(&buf, KERN_ERR "Oops....\n");

	print_line(&buf, KERN_ERR "continuation line: foo");
	print_line(&buf, KERN_CONT "bar");
	print_line(&buf, KERN_CONT "baz\n");
	...

	print_line(&buf, KERN_ERR "....\n");
	...
	print_line(&buf, KERN_ERR "--- end of oops ---\n");
	emit_printk_buffer(&buf);

so that not only concatenated continuation lines will be handled,
but also more complex things. like backtraces or whatever someone
might want to handle.

	-ss

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-08-29 20:24     ` Pavel Machek
@ 2017-09-01  1:40       ` Sergey Senozhatsky
  2017-09-01  2:04         ` Joe Perches
  2017-09-01  7:29         ` Pavel Machek
  0 siblings, 2 replies; 94+ messages in thread
From: Sergey Senozhatsky @ 2017-09-01  1:40 UTC (permalink / raw)
  To: Pavel Machek
  Cc: Linus Torvalds, Sergey Senozhatsky, Petr Mladek, Steven Rostedt,
	Jan Kara, Andrew Morton, Jiri Slaby, Andreas Mohr, Tetsuo Handa,
	Linux Kernel Mailing List, Sergey Senozhatsky

Hi,

On (08/29/17 22:24), Pavel Machek wrote:
> > > In 4.13-rc, printk("foo"); printk("bar"); seems to produce
> > > foo\nbar. That's... quite surprising/unwelcome. What is going on
> > > there? Are timestamps responsible?
> > 
> > No.
> > 
> > It's actively trying to treach you not to do shit.
> > 
> > If you want to continue a line, you NEED to use KERN_CONT.
> > 
> > That has always been true. It hasn't always been enforced, though.
> 
> Dumping hex buffer for debugging should not be a rocket science. You
> are welcome not add checkpatch rules to prevent such code from being
> merged...

well... just a note, I personally developed a new habit - use
pr_err/pr_cont/etc macros instead of explicit printk(KERN_FOO "...").
may be this can work for you. and we _probably_ need to advertise
pr_foo() more.

	-ss

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-09-01  1:40       ` Sergey Senozhatsky
@ 2017-09-01  2:04         ` Joe Perches
  2017-09-01  6:59           ` Pavel Machek
  2017-09-01  7:29         ` Pavel Machek
  1 sibling, 1 reply; 94+ messages in thread
From: Joe Perches @ 2017-09-01  2:04 UTC (permalink / raw)
  To: Sergey Senozhatsky, Pavel Machek
  Cc: Linus Torvalds, Sergey Senozhatsky, Petr Mladek, Steven Rostedt,
	Jan Kara, Andrew Morton, Jiri Slaby, Andreas Mohr, Tetsuo Handa,
	Linux Kernel Mailing List

On Fri, 2017-09-01 at 10:40 +0900, Sergey Senozhatsky wrote:
> On (08/29/17 22:24), Pavel Machek wrote:
> > > > In 4.13-rc, printk("foo"); printk("bar"); seems to produce
> > > > foo\nbar. That's... quite surprising/unwelcome. What is going on
> > > > there? Are timestamps responsible?
[]
> > You are welcome not add checkpatch rules to prevent such code from being
> > merged...

Pavel, what does this mean?

> well... just a note, I personally developed a new habit - use
> pr_err/pr_cont/etc macros instead of explicit printk(KERN_FOO "...").
> may be this can work for you. and we _probably_ need to advertise
> pr_foo() more.

As well as convert the macros to functions
to save some .text too.

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-09-01  2:04         ` Joe Perches
@ 2017-09-01  6:59           ` Pavel Machek
  2017-09-01  7:23             ` Joe Perches
  0 siblings, 1 reply; 94+ messages in thread
From: Pavel Machek @ 2017-09-01  6:59 UTC (permalink / raw)
  To: Joe Perches
  Cc: Sergey Senozhatsky, Linus Torvalds, Sergey Senozhatsky,
	Petr Mladek, Steven Rostedt, Jan Kara, Andrew Morton, Jiri Slaby,
	Andreas Mohr, Tetsuo Handa, Linux Kernel Mailing List

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

On Thu 2017-08-31 19:04:24, Joe Perches wrote:
> On Fri, 2017-09-01 at 10:40 +0900, Sergey Senozhatsky wrote:
> > On (08/29/17 22:24), Pavel Machek wrote:
> > > > > In 4.13-rc, printk("foo"); printk("bar"); seems to produce
> > > > > foo\nbar. That's... quite surprising/unwelcome. What is going on
> > > > > there? Are timestamps responsible?
> []
> > > You are welcome not add checkpatch rules to prevent such code from being
> > > merged...
> 
> Pavel, what does this mean?

That should have been "welcome to".

> > well... just a note, I personally developed a new habit - use
> > pr_err/pr_cont/etc macros instead of explicit printk(KERN_FOO "...").
> > may be this can work for you. and we _probably_ need to advertise
> > pr_foo() more.
> 
> As well as convert the macros to functions
> to save some .text too.

IMO pr_foo() is bad interface for debugging. I don't care about
loglevels at that point, I just want to see the data... and difference
from userspace debugging actually hurts there.

Yes, I could train my fingers to just do pr_cont(), always, but
training fingers is hard.

									Pavel
-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 181 bytes --]

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-09-01  6:59           ` Pavel Machek
@ 2017-09-01  7:23             ` Joe Perches
  0 siblings, 0 replies; 94+ messages in thread
From: Joe Perches @ 2017-09-01  7:23 UTC (permalink / raw)
  To: Pavel Machek
  Cc: Sergey Senozhatsky, Linus Torvalds, Sergey Senozhatsky,
	Petr Mladek, Steven Rostedt, Jan Kara, Andrew Morton, Jiri Slaby,
	Andreas Mohr, Tetsuo Handa, Linux Kernel Mailing List

On Fri, 2017-09-01 at 08:59 +0200, Pavel Machek wrote:
> On Thu 2017-08-31 19:04:24, Joe Perches wrote:
> > On Fri, 2017-09-01 at 10:40 +0900, Sergey Senozhatsky wrote:
> > > On (08/29/17 22:24), Pavel Machek wrote:
> > > > > > In 4.13-rc, printk("foo"); printk("bar"); seems to produce
> > > > > > foo\nbar. That's... quite surprising/unwelcome. What is going on
> > > > > > there? Are timestamps responsible?
> > []
> > > > You are welcome not add checkpatch rules to prevent such code from being
> > > > merged...
> > 
> > Pavel, what does this mean?
> That should have been "welcome to".

Right.

Good luck with a checkpatch implementation.

> IMO pr_foo() is bad interface for debugging.

Why?

> I just want to see the data... and difference
> from userspace debugging actually hurts there.

How so?  What data is not available?

Making functions of the various pr_<level> uses
makes it easier to insert things like singletons
for any pr_fmt prefix which could save a few KB
and as well allow for centralized mechanisms to
emit logging messages with
	%ps, __builtin_return_address(0)
instead of using
	"%s <fmt>", __func__, args...
to save even more space.

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-09-01  1:40       ` Sergey Senozhatsky
  2017-09-01  2:04         ` Joe Perches
@ 2017-09-01  7:29         ` Pavel Machek
  2017-09-01 11:13           ` Steven Rostedt
  1 sibling, 1 reply; 94+ messages in thread
From: Pavel Machek @ 2017-09-01  7:29 UTC (permalink / raw)
  To: Sergey Senozhatsky
  Cc: Linus Torvalds, Sergey Senozhatsky, Petr Mladek, Steven Rostedt,
	Jan Kara, Andrew Morton, Jiri Slaby, Andreas Mohr, Tetsuo Handa,
	Linux Kernel Mailing List

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

On Fri 2017-09-01 10:40:12, Sergey Senozhatsky wrote:
> Hi,
> 
> On (08/29/17 22:24), Pavel Machek wrote:
> > > > In 4.13-rc, printk("foo"); printk("bar"); seems to produce
> > > > foo\nbar. That's... quite surprising/unwelcome. What is going on
> > > > there? Are timestamps responsible?
> > > 
> > > No.
> > > 
> > > It's actively trying to treach you not to do shit.
> > > 
> > > If you want to continue a line, you NEED to use KERN_CONT.
> > > 
> > > That has always been true. It hasn't always been enforced, though.
> > 
> > Dumping hex buffer for debugging should not be a rocket science. You
> > are welcome not add checkpatch rules to prevent such code from being
> > merged...
> 
> well... just a note, I personally developed a new habit - use
> pr_err/pr_cont/etc macros instead of explicit printk(KERN_FOO "...").
> may be this can work for you. and we _probably_ need to advertise
> pr_foo() more.

Well, usually dev_info (and friends) is right thing to use for
production. But very little debugging remains after the
.. well.. debugging phase, so something that behaves similar to
printf() is nice.

Actually, I believe we should just create printf() in kernel. Its the
mistake I do all the time.

									Pavel
-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 181 bytes --]

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-09-01  7:29         ` Pavel Machek
@ 2017-09-01 11:13           ` Steven Rostedt
  0 siblings, 0 replies; 94+ messages in thread
From: Steven Rostedt @ 2017-09-01 11:13 UTC (permalink / raw)
  To: Pavel Machek
  Cc: Sergey Senozhatsky, Linus Torvalds, Sergey Senozhatsky,
	Petr Mladek, Jan Kara, Andrew Morton, Jiri Slaby, Andreas Mohr,
	Tetsuo Handa, Linux Kernel Mailing List

On Fri, 1 Sep 2017 09:29:06 +0200
Pavel Machek <pavel@ucw.cz> wrote:


> Well, usually dev_info (and friends) is right thing to use for
> production. But very little debugging remains after the
> .. well.. debugging phase, so something that behaves similar to
> printf() is nice.

Try using trace_printk(). Who uses printk() to debug anymore ;-)

> 
> Actually, I believe we should just create printf() in kernel. Its the
> mistake I do all the time.

It's a way to tell you how much user vs kernel programming you do. When
you type printk() in user space, you know you've been doing more kernel
programming. When you type printf() in kernel space, you've been doing
more user space programming.

-- Steve

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-08-30  1:10                   ` Steven Rostedt
  2017-08-30  1:51                     ` Sergey Senozhatsky
  2017-08-30  1:52                     ` Joe Perches
@ 2017-09-01 13:19                     ` Sergey Senozhatsky
  2017-09-01 17:32                       ` Joe Perches
  2 siblings, 1 reply; 94+ messages in thread
From: Sergey Senozhatsky @ 2017-09-01 13:19 UTC (permalink / raw)
  To: Steven Rostedt
  Cc: Sergey Senozhatsky, Linus Torvalds, Pavel Machek,
	Sergey Senozhatsky, Petr Mladek, Jan Kara, Andrew Morton,
	Jiri Slaby, Andreas Mohr, Tetsuo Handa,
	Linux Kernel Mailing List

On (08/29/17 21:10), Steven Rostedt wrote:
[..]
> > could do. for a single continuation line printk("%.*s", s.len, s.buffer)
> > this will work perfectly fine. for a more general case - backtraces, dumps,
> > etc. - this requires some tweaks.
> 
> We could simply add a seq_buf_printk() that is implemented in the printk
> proper, to parse the seq_buf buffer properly, and add the timestamps and
> such.

so I quickly cooked the first version. like really quickly. just to
check if this is what people might like/use.

RFC.

so wondering if this will suffice. the name is somewhat hideous -- prbuf(),
wanted to keep it short and somehow aligned with pr_foo().

the patch also defines a number of prbuf_err()/prbuf_cont() macros that
call __prbuf_write() -- I don't want people to invoke __prbuf_write()
directly, because we need KERN_FOO prefix for stored messages and people
tend to forget to provide one.

prbuf_init() function inits the seq_buf buffer. it takes size and GFP
mask, just to permit prbuf usage from different contexts. if we fail
to kmalloc() the buffer, then __prbuf_write() does direct printk().

a usage example:


       struct seq_buf s;

       prbuf_init(&s, 256, GFP_KERNEL);

       prbuf_err(&s, "Opps at %lu\n", _RET_IP_);
       prbuf_info(&s, "Start of cont line");
       prbuf_cont(&s, " foo ");
       prbuf_cont(&s, " bar ");
       prbuf_cont(&s, " status: %s\n", "done");

       ret = 0;
       while (ret++ < 10)
               prbuf_err(&s, "%x\n", ret);

       prbuf_flush(&s);
       prbuf_free(&s);


this will store everything in conseq logbuf entries. if the buffer
was too small, we print overflow message.

any comments?

---
 include/linux/printk.h |  58 ++++++++++++++++
 kernel/printk/printk.c | 178 +++++++++++++++++++++++++++++++++++++++++--------
 2 files changed, 209 insertions(+), 27 deletions(-)

diff --git a/include/linux/printk.h b/include/linux/printk.h
index e10f27468322..ab39b85cff8e 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -206,6 +206,17 @@ void show_regs_print_info(const char *log_lvl);
 extern void printk_safe_init(void);
 extern void printk_safe_flush(void);
 extern void printk_safe_flush_on_panic(void);
+
+struct seq_buf;
+
+extern int prbuf_init(struct seq_buf *s, size_t size, gfp_t flags);
+
+extern __printf(2, 3) __cold
+int __prbuf_write(struct seq_buf *s, const char *fmt, ...);
+
+extern int prbuf_flush(struct seq_buf *s);
+
+extern void prbuf_free(struct seq_buf *s);
 #else
 static inline __printf(1, 0)
 int vprintk(const char *s, va_list args)
@@ -277,6 +288,29 @@ static inline void printk_safe_flush(void)
 static inline void printk_safe_flush_on_panic(void)
 {
 }
+
+struct seq_buf;
+
+static inline
+int prbuf_init(struct seq_buf *s, size_t size, gfp_t flags)
+{
+	return 0;
+}
+
+static inlin __printf(2, 3) __cold
+static int __prbuf_write(struct seq_buf *s, const char *fmt, ...)
+{
+	return 0;
+}
+
+static inline int prbuf_flush(struct seq_buf *s)
+{
+	return 0;
+}
+
+static inline void prbuf_free(struct seq_buf *s)
+{
+}
 #endif
 
 extern asmlinkage void dump_stack(void) __cold;
@@ -323,6 +357,30 @@ extern asmlinkage void dump_stack(void) __cold;
 	no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
 #endif
 
+/*
+ * Macros for buffered printk. All messages are stored in seq_buf instead of
+ * logbuf, user is required to flush the buffer in order to emit the messages
+ * and move them to the logbuf.
+ *
+ * Please use these macros and never call __prbuf_write() directly.
+ */
+#define prbuf_emerg(s, fmt, ...) \
+	__prbuf_write((s). KERN_EMERG pr_fmt(fmt), ##__VA_ARGS__)
+#define prbuf_alert(s, fmt, ...) \
+	__prbuf_write((s), KERN_ALERT pr_fmt(fmt), ##__VA_ARGS__)
+#define prbuf_crit(s, fmt, ...) \
+	__prbuf_write((s), KERN_CRIT pr_fmt(fmt), ##__VA_ARGS__)
+#define prbuf_err(s, fmt, ...) \
+	__prbuf_write((s), KERN_ERR pr_fmt(fmt), ##__VA_ARGS__)
+#define prbuf_warning(s, fmt, ...) \
+	__prbuf_write((s), KERN_WARNING pr_fmt(fmt), ##__VA_ARGS__)
+#define prbuf_warn pr_buf_warning
+#define prbuf_notice(s, fmt, ...) \
+	__prbuf_write((s), KERN_NOTICE pr_fmt(fmt), ##__VA_ARGS__)
+#define prbuf_info(s, fmt, ...) \
+	__prbuf_write((s), KERN_INFO pr_fmt(fmt), ##__VA_ARGS__)
+#define prbuf_cont(s, fmt, ...) \
+	__prbuf_write((s), KERN_CONT fmt, ##__VA_ARGS__)
 
 /* If you are writing a driver, please use dev_dbg instead */
 #if defined(CONFIG_DYNAMIC_DEBUG)
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 512f7c2baedd..6ccc7edda3a4 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -48,6 +48,7 @@
 #include <linux/sched/clock.h>
 #include <linux/sched/debug.h>
 #include <linux/sched/task_stack.h>
+#include <linux/seq_buf.h>
 
 #include <linux/uaccess.h>
 #include <asm/sections.h>
@@ -1651,7 +1652,9 @@ static bool cont_add(int facility, int level, enum log_flags flags, const char *
 	return true;
 }
 
-static size_t log_output(int facility, int level, enum log_flags lflags, const char *dict, size_t dictlen, char *text, size_t text_len)
+static size_t log_output(int facility, int level, enum log_flags lflags,
+			 const char *dict, size_t dictlen,
+			 const char *text, size_t text_len)
 {
 	/*
 	 * If an earlier line was buffered, and we're a continuation
@@ -1680,33 +1683,11 @@ static size_t log_output(int facility, int level, enum log_flags lflags, const c
 	return log_store(facility, level, lflags, 0, dict, dictlen, text, text_len);
 }
 
-asmlinkage int vprintk_emit(int facility, int level,
-			    const char *dict, size_t dictlen,
-			    const char *fmt, va_list args)
+static int process_log(int facility, int level,
+		       const char *dict, size_t dictlen,
+		       const char *text, size_t text_len)
 {
-	static char textbuf[LOG_LINE_MAX];
-	char *text = textbuf;
-	size_t text_len;
 	enum log_flags lflags = 0;
-	unsigned long flags;
-	int printed_len;
-	bool in_sched = false;
-
-	if (level == LOGLEVEL_SCHED) {
-		level = LOGLEVEL_DEFAULT;
-		in_sched = true;
-	}
-
-	boot_delay_msec(level);
-	printk_delay();
-
-	/* This stops the holder of console_sem just where we want him */
-	logbuf_lock_irqsave(flags);
-	/*
-	 * The printf needs to come first; we need the syslog
-	 * prefix which might be passed-in as a parameter.
-	 */
-	text_len = vscnprintf(text, sizeof(textbuf), fmt, args);
 
 	/* mark and strip a trailing newline */
 	if (text_len && text[text_len-1] == '\n') {
@@ -1742,8 +1723,38 @@ asmlinkage int vprintk_emit(int facility, int level,
 	if (dict)
 		lflags |= LOG_PREFIX|LOG_NEWLINE;
 
-	printed_len = log_output(facility, level, lflags, dict, dictlen, text, text_len);
+	return log_output(facility, level, lflags, dict, dictlen, text, text_len);
+}
+
+asmlinkage int vprintk_emit(int facility, int level,
+			    const char *dict, size_t dictlen,
+			    const char *fmt, va_list args)
+{
+	static char textbuf[LOG_LINE_MAX];
+	char *text = textbuf;
+	size_t text_len;
+	unsigned long flags;
+	int printed_len;
+	bool in_sched = false;
+
+	if (level == LOGLEVEL_SCHED) {
+		level = LOGLEVEL_DEFAULT;
+		in_sched = true;
+	}
+
+	boot_delay_msec(level);
+	printk_delay();
 
+	/* This stops the holder of console_sem just where we want him */
+	logbuf_lock_irqsave(flags);
+	/*
+	 * The printf needs to come first; we need the syslog
+	 * prefix which might be passed-in as a parameter.
+	 */
+	text_len = vscnprintf(text, sizeof(textbuf), fmt, args);
+	printed_len = process_log(facility, level,
+				  dict, dictlen,
+				  text, text_len);
 	logbuf_unlock_irqrestore(flags);
 
 	/* If called from the scheduler, we can not call up(). */
@@ -1833,6 +1844,119 @@ asmlinkage __visible int printk(const char *fmt, ...)
 }
 EXPORT_SYMBOL(printk);
 
+int prbuf_init(struct seq_buf *s, size_t size, gfp_t flags)
+{
+	char *b;
+
+	b = kmalloc(size, flags);
+	seq_buf_init(s, b, size);
+	return !!b;
+}
+EXPORT_SYMBOL(prbuf_init);
+
+/*
+ * Do not use this function directly. Use dedicated macros instead.
+ *
+ * If you'll you use this function, Linus will kindly ask you to
+ * consider other options.
+ */
+int __prbuf_write(struct seq_buf *s, const char *fmt, ...)
+{
+	va_list args;
+	int r;
+
+	va_start(args, fmt);
+	if (likely(s->buffer))
+		r = seq_buf_vprintf(s, fmt, args);
+	else
+		r = vprintk_func(fmt, args);
+	va_end(args);
+
+	return r;
+}
+EXPORT_SYMBOL(__prbuf_write);
+
+int prbuf_flush(struct seq_buf *s)
+{
+	unsigned long flags;
+	const char *start, *c, *end;
+	bool header;
+	int len = 0;
+
+	if (!s->buffer)
+		return 0;
+
+	start = s->buffer;
+	c = start;
+	end = start + seq_buf_used(s);
+	header = true;
+
+	logbuf_lock_irqsave(flags);
+
+	if (seq_buf_has_overflowed(s)) {
+		static const char *msg = KERN_ERR "Print buffer overflow\n";
+
+		len += process_log(0, LOGLEVEL_DEFAULT,
+				   NULL, 0,
+				   msg, strlen(msg));
+	}
+
+	/* Print line by line. */
+	while (c < end) {
+		if (*c == '\n') {
+			len += process_log(0, LOGLEVEL_DEFAULT,
+					   NULL, 0,
+					   start, c - start + 1);
+			start = ++c;
+			header = true;
+			continue;
+		}
+
+		/* Handle continuous lines or missing new line. */
+		if ((c + 1 < end) && printk_get_level(c)) {
+			if (header) {
+				c = printk_skip_level(c);
+				continue;
+			}
+
+			len += process_log(0, LOGLEVEL_DEFAULT,
+					   NULL, 0,
+					   start, c - start);
+			start = c++;
+			header = true;
+			continue;
+		}
+
+		header = false;
+		c++;
+	}
+
+	/* Check if there was a partial line. Ignore pure header. */
+	if (start < end && !header) {
+		static const char *newline = KERN_CONT "\n";
+
+		len += process_log(0, LOGLEVEL_DEFAULT,
+				   NULL, 0,
+				   start, end - start);
+		len += process_log(0, LOGLEVEL_DEFAULT,
+				   NULL, 0,
+				   newline, strlen(newline));
+	}
+
+	logbuf_unlock_irqrestore(flags);
+
+	seq_buf_clear(s);
+	return len;
+}
+EXPORT_SYMBOL(prbuf_flush);
+
+void prbuf_free(struct seq_buf *s)
+{
+	kfree(s->buffer);
+	seq_buf_init(s, NULL, 0);
+}
+EXPORT_SYMBOL(prbuf_free);
+
 #else /* CONFIG_PRINTK */
 
 #define LOG_LINE_MAX		0
-- 
2.14.1

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-09-01 13:19                     ` Sergey Senozhatsky
@ 2017-09-01 17:32                       ` Joe Perches
  2017-09-01 20:21                         ` Linus Torvalds
  2017-09-04  4:30                         ` Sergey Senozhatsky
  0 siblings, 2 replies; 94+ messages in thread
From: Joe Perches @ 2017-09-01 17:32 UTC (permalink / raw)
  To: Sergey Senozhatsky, Steven Rostedt
  Cc: Sergey Senozhatsky, Linus Torvalds, Pavel Machek, Petr Mladek,
	Jan Kara, Andrew Morton, Jiri Slaby, Andreas Mohr, Tetsuo Handa,
	Linux Kernel Mailing List

On Fri, 2017-09-01 at 22:19 +0900, Sergey Senozhatsky wrote:
> On (08/29/17 21:10), Steven Rostedt wrote:
> [..]
> > > could do. for a single continuation line printk("%.*s", s.len, s.buffer)
> > > this will work perfectly fine. for a more general case - backtraces, dumps,
> > > etc. - this requires some tweaks.
> > 
> > We could simply add a seq_buf_printk() that is implemented in the printk
> > proper, to parse the seq_buf buffer properly, and add the timestamps and
> > such.
> 
> so I quickly cooked the first version. like really quickly. just to
> check if this is what people might like/use.
> 
> RFC.
> 
> so wondering if this will suffice. the name is somewhat hideous -- prbuf(),
> wanted to keep it short and somehow aligned with pr_foo().

Yes, it's a poor name.  At least keep using a pr_ prefix.

> the patch also defines a number of prbuf_err()/prbuf_cont() macros that
> call __prbuf_write() -- I don't want people to invoke __prbuf_write()
> directly, because we need KERN_FOO prefix for stored messages and people
> tend to forget to provide one.

> prbuf_init() function inits the seq_buf buffer. it takes size and GFP
> mask, just to permit prbuf usage from different contexts. if we fail
> to kmalloc() the buffer, then __prbuf_write() does direct printk().

I think there's relatively little value in multiple line output.
It seems like buffering for buffering's sake.
Just keep it to a single line and simple.

> a usage example:
> 
> 
>        struct seq_buf s;
> 
>        prbuf_init(&s, 256, GFP_KERNEL);
> 
>        prbuf_err(&s, "Opps at %lu\n", _RET_IP_);
>        prbuf_info(&s, "Start of cont line");
>        prbuf_cont(&s, " foo ");
>        prbuf_cont(&s, " bar ");
>        prbuf_cont(&s, " status: %s\n", "done");
> 
>        ret = 0;
>        while (ret++ < 10)
>                prbuf_err(&s, "%x\n", ret);
> 
>        prbuf_flush(&s);
>        prbuf_free(&s);
> 
> 
> this will store everything in conseq logbuf entries. if the buffer
> was too small, we print overflow message.
> 
> any comments?
[]
> diff --git a/include/linux/printk.h b/include/linux/printk.h
[]
> @@ -277,6 +288,29 @@ static inline void printk_safe_flush(void)
>  static inline void printk_safe_flush_on_panic(void)
>  {
>  }
> +
> +struct seq_buf;
> +
> +static inline
> +int prbuf_init(struct seq_buf *s, size_t size, gfp_t flags)
> +{
> +	return 0;
> +}
> +
> +static inlin __printf(2, 3) __cold

uncompiled

> +static int __prbuf_write(struct seq_buf *s, const char *fmt, ...)

inline

> +int prbuf_init(struct seq_buf *s, size_t size, gfp_t flags)
> +{
> +	char *b;
> +
> +	b = kmalloc(size, flags);
> +	seq_buf_init(s, b, size);
> +	return !!b;
> +}

Most of the time, this buffer should be on the stack
and not be malloc'd.

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-09-01 17:32                       ` Joe Perches
@ 2017-09-01 20:21                         ` Linus Torvalds
  2017-09-04  5:22                           ` Sergey Senozhatsky
  2017-09-04  4:30                         ` Sergey Senozhatsky
  1 sibling, 1 reply; 94+ messages in thread
From: Linus Torvalds @ 2017-09-01 20:21 UTC (permalink / raw)
  To: Joe Perches
  Cc: Sergey Senozhatsky, Steven Rostedt, Sergey Senozhatsky,
	Pavel Machek, Petr Mladek, Jan Kara, Andrew Morton, Jiri Slaby,
	Andreas Mohr, Tetsuo Handa, Linux Kernel Mailing List

On Fri, Sep 1, 2017 at 10:32 AM, Joe Perches <joe@perches.com> wrote:
>
> Yes, it's a poor name.  At least keep using a pr_ prefix.

I'd suggest perhaps just "pr_line()".

And instead of having those "err/info/cont" variations, the severity
level should just be set at initialization time.  Not different
versions of "pr_line()".

There's no point to having different severity variations, since the
*only* reason for this would be for buffering. So "pr_cont()" is kind
of assumed for everything but the first.

And even if you end up doing multiple lines, if you actually do
different severities, you damn well shouldn't buffer them together.
They are clearly different things!

               Linus

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-08-29 20:51                 ` Linus Torvalds
@ 2017-09-02  6:12                   ` Tetsuo Handa
  2017-09-02 17:06                     ` Linus Torvalds
  0 siblings, 1 reply; 94+ messages in thread
From: Tetsuo Handa @ 2017-09-02  6:12 UTC (permalink / raw)
  To: torvalds
  Cc: sergey.senozhatsky.work, pavel, sergey.senozhatsky, pmladek,
	rostedt, jack, akpm, jslaby, andi, linux-kernel

Linus Torvalds wrote:
> On Tue, Aug 29, 2017 at 1:41 PM, Tetsuo Handa
> <penguin-kernel@i-love.sakura.ne.jp> wrote:
> >>
> >> A private buffer has none of those issues.
> >
> > Yes, I posted "[PATCH] printk: Add best-effort printk() buffering." at
> > http://lkml.kernel.org/r/1493560477-3016-1-git-send-email-penguin-kernel@I-love.SAKURA.ne.jp .
> 
> No, this is exactly what I *don't* want, because it takes over printk() itself.
> 
> And that's problematic, because nesting happens for various reasons.
> 
> For example, you try to handle that nesting with printk_context(), and
> nothing when an interrupt happens.
> 
> But that is fundamentally broken.
> 
> Just to give an example: what if an interrupt happens, it does this
> buffering thing, then it gets interrupted by *another* interrupt, and
> now the printk from that other interrupt gets incorrectly nested
> together with the first one, because your "printk_context()" gives
> them the same context?

My assumption was that

  (1) task context can be preempted by soft IRQ context, hard IRQ context and NMI context.
  (2) soft IRQ context can be preempted by hard IRQ context and NMI context.
  (3) hard IRQ context can be preempted by NMI context.
  (4) An kernel-oops event can interrupt task context, soft IRQ context, hard IRQ context
      and NMI context, but the interrupted context can not continue execution of
      vprintk_default() after returning from the kernel-oops event even if the
      kernel-oops event occurred in schedulable context and panic_on_oops == 0.

and thus my "printk_context()" gives them different context.

But my assumption was wrong that

  soft IRQ context can be preempted by different soft IRQ context
  (e.g. SoftIRQ1 can be preempted by SoftIRQ2 while running
  handler for SoftIRQ1, and SoftIRQ2 can be preempted by SoftIRQ3
  while running handler for SoftIRQ2, and so on)

  hard IRQ context can be preempted by different hard IRQ context
  (e.g. HardIRQ1 can be preempted by HardIRQ2 while running
  handler for HardIRQ1, and HardIRQ2 can be preempted by HardIRQ3
  while running handler for HardIRQ2, and so on)

? Then, we need to recognize how many IRQs are nested.

I just tried to distinguish context using one "unsigned long" value
by embedding IRQ status into lower bits of "struct task_struct *".
I can change to distinguish context using multiple "unsigned long" values.

> 
> And it really doesn't have to even be interrupts. Look at what happens
> if you take a page fault in kernel space. Same exact deal. Both are
> sleeping contexts.

Is merging messages from outside a page fault and inside a page fault
so serious? That would happen only if memory access which might cause
a page fault occurs between get_printk_buffer() and put_printk_buffer(),
and I think that such user is rare.

> 
> So I really think that the only thing that knows what the "context" is
> is the person who does the printing. So if you want to create a
> printing buffer, it should be explicit. You allocate the buffer ahead
> of time (perhaps on the stack, possibly using actual allocations), and
> you use that explicit context.

If my assumption was wrong, isn't it dangerous from stack usage point of
view that we try to call kmalloc() (or allocate from stack memory) for
prbuf_init() for each nested level because it is theoretically possible
that a different IRQ jumps in while kmalloc() is in progress (or stack
memory is in use)?

> 
> Yes, it means that you don't do "printk()". You do an actual
> "buf_print()" or similar.
> 
>              Linus
> 

My worry is that there are so many functions which will need to receive
"struct seq_buf *" argument (from tail of __dump_stack() to head of
out_of_memory(), including e.g. cpuset_print_current_mems_allowed()) that
patches for passing "struct seq_buf *" argument becomes so large and
difficult to synchronize. I tried to pass such argument to relevant
functions before I propose "[PATCH] printk: Add best-effort printk()
buffering." patch, but I came to conclusion that passing such argument is
too complicated and too much bloat compared to merit.

If we teach printk subsystem that "I want to use buffering" via
get_printk_buffer(), we don't need to scatter around "struct seq_buf *"
argument throughout the kernel.

Using kmalloc() for prbuf_init() also introduces problems such as

  (a) we need to care about safe GFP flags (i.e. GFP_ATOMIC or
      GFP_KERNEL or something else which cannot be managed by
      current_gfp_context()) based on locking context

  (b) allocations can fail, and printing allocation failure messages
      when printing original messages is disturbing

  (c) allocation stall/failure messages are printed under memory pressure,
      but stack memory is not large enough to store messages related
      allocation stall/failure messages

and thus I want to use "statically allocated buffer" like workqueue's
rescuer kernel thread which can be used under memory pressure.

Linus Torvalds wrote at http://lkml.kernel.org/r/CA+55aFxmL4ybpz19OPn97VYqAk2ZS-tf=0W2Ff1K=-UUB6mYyg@mail.gmail.com :
> On Fri, Sep 1, 2017 at 10:32 AM, Joe Perches <joe@perches.com> wrote:
> >
> > Yes, it's a poor name.  At least keep using a pr_ prefix.
> 
> I'd suggest perhaps just "pr_line()".
> 
> And instead of having those "err/info/cont" variations, the severity
> level should just be set at initialization time.  Not different
> versions of "pr_line()".
> 
> There's no point to having different severity variations, since the
> *only* reason for this would be for buffering. So "pr_cont()" is kind
> of assumed for everything but the first.

But it is annoying for me that

  Lines1-for-event1-with-loglevel-foo
  Lines2-for-event1-with-loglevel-bar
  Lines3-for-event1-with-loglevel-baz

(like OOM killer messages) are all treated as loglevel foo
breaks console_loglevel filtering and

> 
> And even if you end up doing multiple lines, if you actually do
> different severities, you damn well shouldn't buffer them together.
> They are clearly different things!

two series of messages

  Line1-for-event1-with-loglevel-foo
  Line2-for-event1-with-loglevel-bar
  Line3-for-event1-with-loglevel-bar
  Line4-for-event1-with-loglevel-bar
  Line5-for-event1-with-loglevel-baz

by task/1000 and

  Line1-for-event2-with-loglevel-foo
  Line2-for-event2-with-loglevel-bar
  Line3-for-event2-with-loglevel-bar
  Line4-for-event2-with-loglevel-bar
  Line5-for-event2-with-loglevel-baz

by task/1001 are mixed due to not to buffering lines with different
loglevels causes unreadable logs (unless printk() automatically
inserts context identifier into each line like

  foo task/1000 Line1-for-event1-with-loglevel-foo
  foo task/1001 Line1-for-event2-with-loglevel-foo
  bar task/1001 Line2-for-event2-with-loglevel-bar
  bar task/1001 Line3-for-event2-with-loglevel-bar
  bar task/1001 Line4-for-event2-with-loglevel-bar
  bar task/1000 Line2-for-event1-with-loglevel-bar
  bar task/1000 Line3-for-event1-with-loglevel-bar
  bar task/1000 Line4-for-event1-with-loglevel-bar
  baz task/1000 Line5-for-event1-with-loglevel-baz
  baz task/1001 Line5-for-event2-with-loglevel-baz

).

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-09-02  6:12                   ` Tetsuo Handa
@ 2017-09-02 17:06                     ` Linus Torvalds
  0 siblings, 0 replies; 94+ messages in thread
From: Linus Torvalds @ 2017-09-02 17:06 UTC (permalink / raw)
  To: Tetsuo Handa
  Cc: Sergey Senozhatsky, Pavel Machek, SergeySenozhatsky, Petr Mladek,
	Steven Rostedt, Jan Kara, Andrew Morton, Jiri Slaby,
	Andreas Mohr, Linux Kernel Mailing List

On Fri, Sep 1, 2017 at 11:12 PM, Tetsuo Handa
<penguin-kernel@i-love.sakura.ne.jp> wrote:
>
> I just tried to distinguish context using one "unsigned long" value
> by embedding IRQ status into lower bits of "struct task_struct *".
> I can change to distinguish context using multiple "unsigned long" values.

I really really don't think we want to use implicit contexts. I
suspect you'd end up doing something like a per-cpu counter (with
perhaps the CPU number in the low bits or something) and every
exception and sw interrupt etc would increment it.

.. oh, and workqueues etc.

And the end result would be that you'd be very limited in where you
can actually expect buffering to happen.

Which is all a bad design, since just making the buffer explicit is
(a) cheaper and (b) better. Now you can put the buffer on the stack,
you never have to worry about where you need to track context, and you
have no buffering limits (ie you can buffer across any event).

> If my assumption was wrong, isn't it dangerous from stack usage point of
> view that we try to call kmalloc()

I think there might be situations where you want to do that, but since
we're talking _printing_, we also know that the buffering normally is
about a single line.

Sure, some situations might want to buffer more before they print out
(perhaps you want to have guarantees that the register state of an
oops never gets mixed up with anything else, or whatever), and maybe
sometimes you'd want bigger lines.

But I definitely suspect that "single line" is often sufficient. I
mean, that's all that KERN_CONT ever gave you anyway (and not
reliably).

And then a 80 character buffer really isn't any different from having
a structure with a few pointers in it, which we do on the stack all
the time.

                  Linus

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-09-01 17:32                       ` Joe Perches
  2017-09-01 20:21                         ` Linus Torvalds
@ 2017-09-04  4:30                         ` Sergey Senozhatsky
  2017-09-04  5:24                           ` Sergey Senozhatsky
  1 sibling, 1 reply; 94+ messages in thread
From: Sergey Senozhatsky @ 2017-09-04  4:30 UTC (permalink / raw)
  To: Joe Perches
  Cc: Sergey Senozhatsky, Steven Rostedt, Sergey Senozhatsky,
	Linus Torvalds, Pavel Machek, Petr Mladek, Jan Kara,
	Andrew Morton, Jiri Slaby, Andreas Mohr, Tetsuo Handa,
	Linux Kernel Mailing List

On (09/01/17 10:32), Joe Perches wrote:
[..]
> > +static inlin __printf(2, 3) __cold
> 
> uncompiled
> 
> > +static int __prbuf_write(struct seq_buf *s, const char *fmt, ...)
> 
> inline
> 

thanks.

there is always a missing

	if (console_trylock())
		console_unlock();

in flush() function.

	-ss

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-09-01 20:21                         ` Linus Torvalds
@ 2017-09-04  5:22                           ` Sergey Senozhatsky
  2017-09-04  5:41                             ` Joe Perches
  2017-09-05 14:54                             ` Steven Rostedt
  0 siblings, 2 replies; 94+ messages in thread
From: Sergey Senozhatsky @ 2017-09-04  5:22 UTC (permalink / raw)
  To: Linus Torvalds
  Cc: Joe Perches, Sergey Senozhatsky, Steven Rostedt,
	Sergey Senozhatsky, Pavel Machek, Petr Mladek, Jan Kara,
	Andrew Morton, Jiri Slaby, Andreas Mohr, Tetsuo Handa,
	Linux Kernel Mailing List

Hello,

I'll answer to both Linus and Joe, just to keep it all one place.

On (09/01/17 13:21), Linus Torvalds wrote:
> On Fri, Sep 1, 2017 at 10:32 AM, Joe Perches <joe@perches.com> wrote:
> >
> > Yes, it's a poor name.  At least keep using a pr_ prefix.
> 
> I'd suggest perhaps just "pr_line()".

ok, pr_line sound good.

> And instead of having those "err/info/cont" variations, the severity
> level should just be set at initialization time.  Not different
> versions of "pr_line()".
> 
> There's no point to having different severity variations, since the
> *only* reason for this would be for buffering. So "pr_cont()" is kind
> of assumed for everything but the first.
> 
> And even if you end up doing multiple lines, if you actually do
> different severities, you damn well shouldn't buffer them together.
> They are clearly different things!

hm... may be.
the main point of prbuf is not the support of cont lines, but the
fact that buffered messages are added to the logbuf atomically,
and thus are printed in consequent lines, not the usual way:

CPU0	because
CPU1	this
CPU0	it's easier
CPU1	might
CPU0	to read
CPU1	be
CPU1	inconvenient.
CPU0	seq messages.

some people want to be able to make it to look less spaghetti-like:

CPU0	because
CPU0	it's easier
CPU0	to read
CPU0	seq messages.
CPU1	this
CPU1	might
CPU1	be
CPU1	inconvenient.

and it's not something completely wrong to ask for, I think.
well, who knows.

there is only way to serialize printks against other printks -- take
the logbuf lock. and that's what pr_line/prbuf flush is doing.


now, pr_line/prbuf/pr_buf is, of course, very limited. it should NOT
be used for things that are really important and absolutely must [if
possible] appear in serial logs/on screens/etc. simply because panic
can happen on CPUA before we flush any pending pr_line/prbuf buffers
on other CPUs. and that's exactly the reason why I initially wanted
(and still do) to implement pr_line/prbuf using printk-safe
mechanism - because we flush printk-safe buffers from panic(). so
utilizing printk-safe buffers can make pr_line less fragile. apart
from that printk-safe buffers are always there, so OOM is not a show
stopper anymore. but, like I said in another email, printk-safe buffer
is per-CPU and is also used for actual printk-safe, hence it must be
used with local IRQs disabled when we "borrow" the buffer for pr_line
(disabled preemption is not enough due to possible IRQ printk-safe
print out). this can be a bit annoying.

in it's current form, pr_line/pr_buf is NOT a replacement for pr_cont
or printk(KERN_CONT). because pr_cont has no such thing as "we were
unable to flush the buffer from CPUB because of panic on CPUA". so
pr_cont/printk(KERN_CONT) beats pr_line/pr_buf here. This can be a
major limitation. am I wrong?


another thing,
if we eventually will decide to stick to "use a seq_buf with stack
allocated char buffer to hold a single line only" design, then I'm
not entirely sure I get it why do we want to add a new API at all.
I mean, the new API does not make anything simpler or shorter. we
need to declare the buffer, seq_buf, init seq_buf, append chars to
seq_buf, flush it:

	char buf[80];
	struct seq_buf cont_line;

	pr_line_init(&cont_line, buf, sizeof(buf));
	pr_line_printf(&cont_line, "....");
	pr_line_printf(&cont_line, "....");
	pr_line_flush(&cont_line);

this asks for  s/pr_line_/seq_buf_/g, no? well, except for the flush()
part. it can be replaced with printk("%s\n", cont_line->buffer).

so it seems that we need to re-think it.

	-ss

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-09-04  4:30                         ` Sergey Senozhatsky
@ 2017-09-04  5:24                           ` Sergey Senozhatsky
  0 siblings, 0 replies; 94+ messages in thread
From: Sergey Senozhatsky @ 2017-09-04  5:24 UTC (permalink / raw)
  To: Sergey Senozhatsky
  Cc: Joe Perches, Sergey Senozhatsky, Steven Rostedt, Linus Torvalds,
	Pavel Machek, Petr Mladek, Jan Kara, Andrew Morton, Jiri Slaby,
	Andreas Mohr, Tetsuo Handa, Linux Kernel Mailing List

On (09/04/17 13:30), Sergey Senozhatsky wrote:
> On (09/01/17 10:32), Joe Perches wrote:
> [..]
> > > +static inlin __printf(2, 3) __cold
> > 
> > uncompiled
> > 
> > > +static int __prbuf_write(struct seq_buf *s, const char *fmt, ...)
> > 
> > inline
> > 
> 
> thanks.
> 
> there is always a missing

d'oh...  s/always/also/

	-ss

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-09-04  5:22                           ` Sergey Senozhatsky
@ 2017-09-04  5:41                             ` Joe Perches
  2017-09-05 14:54                             ` Steven Rostedt
  1 sibling, 0 replies; 94+ messages in thread
From: Joe Perches @ 2017-09-04  5:41 UTC (permalink / raw)
  To: Sergey Senozhatsky, Linus Torvalds
  Cc: Sergey Senozhatsky, Steven Rostedt, Pavel Machek, Petr Mladek,
	Jan Kara, Andrew Morton, Jiri Slaby, Andreas Mohr, Tetsuo Handa,
	Linux Kernel Mailing List

On Mon, 2017-09-04 at 14:22 +0900, Sergey Senozhatsky wrote:
> there is only way to serialize printks against other printks -- take
> the logbuf lock.

If that's really necessary, instead make that
logbuf_lock a public interface and keep the rest
of the code simple.

I think it's more important to get printk to work
reliably than keep expanding the number of lines
possible to buffer.

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-08-30  2:47                           ` Sergey Senozhatsky
  2017-08-30  2:58                             ` Joe Perches
@ 2017-09-05  9:44                             ` Petr Mladek
  2017-09-05  9:59                               ` Sergey Senozhatsky
  1 sibling, 1 reply; 94+ messages in thread
From: Petr Mladek @ 2017-09-05  9:44 UTC (permalink / raw)
  To: Sergey Senozhatsky
  Cc: Joe Perches, Steven Rostedt, Linus Torvalds, Pavel Machek,
	Sergey Senozhatsky, Jan Kara, Andrew Morton, Jiri Slaby,
	Andreas Mohr, Tetsuo Handa, Linux Kernel Mailing List

On Wed 2017-08-30 11:47:03, Sergey Senozhatsky wrote:
> On (08/29/17 19:31), Joe Perches wrote:
> [..]
> > > the idea is not to do printk() on that seq buffer at all, but to
> > > log_store(), atomically, seq buffer messages
> > > 
> > > 	spin_lock(&logbuf_lock)
> > > 	while (offset < seq_buffer->len) {
> > > 		...
> > > 		log_store(seq->buffer + offset);
> > > 		...
> > > 	}
> > > 	spin_unlock(&logbuf_unlock)
> > 
> > Why?
> 
> Tetsuo wants this, for instance,
> for OOM reports and backtraces. SCIS/ATA people want it as well.

The mixing of related lines might cause problems. But I am not sure
if it can be fixed a safe way on the printk side. Especially I am
afraid of an extensive buffering.

My underestanding, of the discussion about printk kthread patchset,
is that printk() has the following priorities:

  1. do not break the system (deadlock, livelock, softlock)
  2. get the message out (suddent death, panic, flood of messages)
  3. keep the message readable (cont lines, related lines)

Any buffering would delay showing the message. It increases
the risk that nobody will see it at all. It is acceptable
in printk_safe() and printk_safe_nmi() because we did not
find a better way to avoid the deadlock. But I am not sure
about any buffering used for a better readability. It is
against the priorities mentioned above.

Well, the buffering might be acceptable for single lines. I mean
to solve KERN_CONT problems. A good API might allow to get rid
of KERN_CONT, and the unreliable and rather complex code around
struct cont in kernel/printk/printk.c.

I would be afraid of adding an API that would allow to
(transparently) redirect printing into a buffer from a huge
amount of code.

Alternative solution would be to print more information
per-line, for example:

   <timestamp> <PID> <context> message

Then you might extract the related lines using a simple
grep. It would be similar to the output of
strace -f -t -o <log> <command>.

Best Regards,
Petr

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-09-05  9:44                             ` Petr Mladek
@ 2017-09-05  9:59                               ` Sergey Senozhatsky
  2017-09-05 12:21                                 ` Petr Mladek
  0 siblings, 1 reply; 94+ messages in thread
From: Sergey Senozhatsky @ 2017-09-05  9:59 UTC (permalink / raw)
  To: Petr Mladek
  Cc: Sergey Senozhatsky, Joe Perches, Steven Rostedt, Linus Torvalds,
	Pavel Machek, Sergey Senozhatsky, Jan Kara, Andrew Morton,
	Jiri Slaby, Andreas Mohr, Tetsuo Handa,
	Linux Kernel Mailing List

On (09/05/17 11:44), Petr Mladek wrote:
[..]
> > Tetsuo wants this, for instance,
> > for OOM reports and backtraces. SCIS/ATA people want it as well.
> 
> The mixing of related lines might cause problems. But I am not sure
> if it can be fixed a safe way on the printk side. Especially I am
> afraid of an extensive buffering.
> 
> My underestanding, of the discussion about printk kthread patchset,
> is that printk() has the following priorities

this discussion is not related to printk ktrehad. it's just the
first messages was posted as a reply to printk kthread patch set,
other than that it's unrelated.


> Any buffering would delay showing the message. It increases
> the risk that nobody will see it at all. It is acceptable
> in printk_safe() and printk_safe_nmi() because we did not
> find a better way to avoid the deadlock.

that's why I want buffered printk to re-use the printk-safe buffer
on that particular CPU [ if buffered printk will ever land ].
printk-safe buffer is not allocated on stack, or kmalloc-ed for
temp usafe, and, more importantly, we flush it from panic().

and I'm not sure that lost messages due to missing panic flush()
can really be an option even for a single cont line buffer. well,
may be it can. printk has a sort of guarantee that messages will
be at some well known location when pr_foo or printk function
returns. buffered printk kills it. and I don't want to have
several "flavors" of printk. printk-safe buffer seems to be the
way to preserve that guarantee.

	-ss

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-09-05  9:59                               ` Sergey Senozhatsky
@ 2017-09-05 12:21                                 ` Petr Mladek
  2017-09-05 12:35                                   ` Tetsuo Handa
  2017-09-05 13:42                                   ` Sergey Senozhatsky
  0 siblings, 2 replies; 94+ messages in thread
From: Petr Mladek @ 2017-09-05 12:21 UTC (permalink / raw)
  To: Sergey Senozhatsky
  Cc: Joe Perches, Steven Rostedt, Linus Torvalds, Pavel Machek,
	Sergey Senozhatsky, Jan Kara, Andrew Morton, Jiri Slaby,
	Andreas Mohr, Tetsuo Handa, Linux Kernel Mailing List

On Tue 2017-09-05 18:59:00, Sergey Senozhatsky wrote:
> On (09/05/17 11:44), Petr Mladek wrote:
> [..]
> > > Tetsuo wants this, for instance,
> > > for OOM reports and backtraces. SCIS/ATA people want it as well.
> > 
> > The mixing of related lines might cause problems. But I am not sure
> > if it can be fixed a safe way on the printk side. Especially I am
> > afraid of an extensive buffering.
> > 
> > My underestanding, of the discussion about printk kthread patchset,
> > is that printk() has the following priorities
> 
> this discussion is not related to printk ktrehad. it's just the
> first messages was posted as a reply to printk kthread patch set,
> other than that it's unrelated.

But it is related in the sense of what people expect from printk().
This has been discussed in all the patchsets that try to avoid
soft-lockups. Any printk() feature or fix must be in sync with
these expectations. See below for more.


> > Any buffering would delay showing the message. It increases
> > the risk that nobody will see it at all. It is acceptable
> > in printk_safe() and printk_safe_nmi() because we did not
> > find a better way to avoid the deadlock.
> 
> that's why I want buffered printk to re-use the printk-safe buffer
> on that particular CPU [ if buffered printk will ever land ].
> printk-safe buffer is not allocated on stack, or kmalloc-ed for
> temp usafe, and, more importantly, we flush it from panic().
> 
> and I'm not sure that lost messages due to missing panic flush()
> can really be an option even for a single cont line buffer. well,
> may be it can. printk has a sort of guarantee that messages will
> be at some well known location when pr_foo or printk function
> returns. buffered printk kills it. and I don't want to have
> several "flavors" of printk. printk-safe buffer seems to be the
> way to preserve that guarantee.

But the well known locations would help only when they are flushed
in panic() or when a crashdump is created. They do not help
in other cases, especially where there is a sudden death.

There are many fears that printk offloading does not have enough
guarantees to actually happen. IMHO, there must be similar fears
that the messages in a temporary buffer will never get flushed.

And there are more risks with this approach:

  + soft-lockups caused by disabled preemption; we would
    need this to stay on the same CPU and use the same buffer

  + broken preempt-count and missing message when one forgets
    to close the buffered section or do it twice

  + lost messages because a per-CPU buffer size limitations

  + races in printk_safe() that is not recursions safe

  + not to say the problems mentioned by Linus as reply
    to the Tetsuo's proposal, see
https://lkml.kernel.org/r/CA+55aFx+5R-vFQfr7+Ok9Yrs2adQ2Ma4fz+S6nCyWHY_-2mrmw@mail.gmail.com


Some of these problems would be solved by a custom buffer.
But you are right. There are less guarantees that it would
get flushed or that it can be found in case of troubles.
Now, I am not sure that it is a good idea to use it even
for a single continuous line.

I wonder if all this is worth the effort, complexity, and risk.
We are talking about cosmetic problems after all.

Well, what do you think about the extra printed information?
For example:

    <timestamp> <PID> <context> message

It looks straightforward to me. These information
might be helpful on its own. So, it might be a
win-win solution.

Best Regards,
Petr

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-09-05 12:21                                 ` Petr Mladek
@ 2017-09-05 12:35                                   ` Tetsuo Handa
  2017-09-05 14:18                                     ` Sergey Senozhatsky
  2017-09-05 13:42                                   ` Sergey Senozhatsky
  1 sibling, 1 reply; 94+ messages in thread
From: Tetsuo Handa @ 2017-09-05 12:35 UTC (permalink / raw)
  To: pmladek, sergey.senozhatsky.work
  Cc: joe, rostedt, torvalds, pavel, sergey.senozhatsky, jack, akpm,
	jslaby, andi, linux-kernel

Petr Mladek wrote:
> Some of these problems would be solved by a custom buffer.
> But you are right. There are less guarantees that it would
> get flushed or that it can be found in case of troubles.
> Now, I am not sure that it is a good idea to use it even
> for a single continuous line.
> 
> I wonder if all this is worth the effort, complexity, and risk.
> We are talking about cosmetic problems after all.
> 
> Well, what do you think about the extra printed information?
> For example:
> 
>     <timestamp> <PID> <context> message
> 
> It looks straightforward to me. These information
> might be helpful on its own. So, it might be a
> win-win solution.

Yes, if buffering multiple lines will not be implemented, I do want
printk context identifier field for each line. I think <PID> <context>
part will be something like TASK#pid (if outside interrupt) or
CPU#cpunum/#irqlevel (if inside interrupt).

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-09-05 12:21                                 ` Petr Mladek
  2017-09-05 12:35                                   ` Tetsuo Handa
@ 2017-09-05 13:42                                   ` Sergey Senozhatsky
  2017-09-06  7:55                                     ` Petr Mladek
  1 sibling, 1 reply; 94+ messages in thread
From: Sergey Senozhatsky @ 2017-09-05 13:42 UTC (permalink / raw)
  To: Petr Mladek
  Cc: Sergey Senozhatsky, Joe Perches, Steven Rostedt, Linus Torvalds,
	Pavel Machek, Sergey Senozhatsky, Jan Kara, Andrew Morton,
	Jiri Slaby, Andreas Mohr, Tetsuo Handa,
	Linux Kernel Mailing List

On (09/05/17 14:21), Petr Mladek wrote:
[..]
> > that's why I want buffered printk to re-use the printk-safe buffer
> > on that particular CPU [ if buffered printk will ever land ].
> > printk-safe buffer is not allocated on stack, or kmalloc-ed for
> > temp usafe, and, more importantly, we flush it from panic().
> > 
> > and I'm not sure that lost messages due to missing panic flush()
> > can really be an option even for a single cont line buffer. well,
> > may be it can. printk has a sort of guarantee that messages will
> > be at some well known location when pr_foo or printk function
> > returns. buffered printk kills it. and I don't want to have
> > several "flavors" of printk. printk-safe buffer seems to be the
> > way to preserve that guarantee.
> 
> But the well known locations would help only when they are flushed
> in panic() or when a crashdump is created. They do not help
> in other cases, especially where there is a sudden death.

if the system locked up and there is no panic()->flush_on_panic(),
no console_unlock(), crashdump, no nothing - then even having
messages in the logbuf is probably not really helpful. you can't
reach them anyway :)
so yes, I'm speaking here about the cases when we flush_on_panic()
or/and generate crash dump.


> There are many fears that printk offloading does not have enough
> guarantees to actually happen. IMHO, there must be similar fears
> that the messages in a temporary buffer will never get flushed.
> 
> And there are more risks with this approach:
> 
>   + soft-lockups caused by disabled preemption; we would
>     need this to stay on the same CPU and use the same buffer

well, yes. like any control path that disables IRQs there are
rules to follow. so printk-safe based solution has limitations.
I mentioned them probably every time I speak about printk-safe
buffering. but those limitations come with a bonus - flush on
panic and well known location of the messages.

one thing to notice, is that
printk-safe is usually faster than printk() or at least as fast as
the fastest printk() path. because, unlike printk, it does not take
spin on the logbuf lock; it does not console_trylock(), it does not
do console_unlock().


>   + broken preempt-count and missing message when one forgets
>     to close the buffered section or do it twice

yes, coding errors are possible.


>   + lost messages because a per-CPU buffer size limitations

which is true for any type of buffers. including logbuf. and
stack allocated buffers, any buffer. printk-safe buffer is at
least much-much bigger than any stack allocated buffer.


>   + races in printk_safe() that is not recursions safe
>
>   + not to say the problems mentioned by Linus as reply
>     to the Tetsuo's proposal, see
> https://lkml.kernel.org/r/CA+55aFx+5R-vFQfr7+Ok9Yrs2adQ2Ma4fz+S6nCyWHY_-2mrmw@mail.gmail.com

like "limited in where you can actually expect buffering to happen"?

sure. it does not come for free, it's not all beautiful and shiny.


[..]
> I wonder if all this is worth the effort, complexity, and risk.
> We are talking about cosmetic problems after all.

the thing about printk-safe buffering is that _mostly_ everything
is already in the kernel. especially if we talk about single cont
line buffering. just add public API printk_buffering_begin() and
printk_buffering_end() that will __printk_safe_enter() and
__printk_safe_exit(). and that's it. unless I'm missing something.

but I'm not super eager to have printk-safe based buffering.
that's why I never posted a patch set. this approach has its
limitations.


> Well, what do you think about the extra printed information?
> For example:
> 
>     <timestamp> <PID> <context> message
> 
> It looks straightforward to me. These information
> might be helpful on its own. So, it might be a
> win-win solution.

hm... don't know. frankly, I never found PID useful. I mostly look
at the serial logs postmortem. so lines
	12231 foo
	21331 bar

are not much better than just
	foo
	bar


I prepend every line with the CPU number that has printk()-ed it.
and that's helpful because one can grep and filter out messages
from other CPUs. it's quite OK thing to have given that messages
can be really mixed sometimes.

so adding extra information to `struct printk_log' could be helpful.
I think we had this discussion before and you didn't want to change
the size of `struct printk_log' because that might break gdb/crash/etc
user space tools. has it changed?

may be we can #ifdef CONFIG_PRINTK_ABC them.

	-ss

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-09-05 12:35                                   ` Tetsuo Handa
@ 2017-09-05 14:18                                     ` Sergey Senozhatsky
  0 siblings, 0 replies; 94+ messages in thread
From: Sergey Senozhatsky @ 2017-09-05 14:18 UTC (permalink / raw)
  To: Tetsuo Handa
  Cc: pmladek, sergey.senozhatsky.work, joe, rostedt, torvalds, pavel,
	sergey.senozhatsky, jack, akpm, jslaby, andi, linux-kernel

On (09/05/17 21:35), Tetsuo Handa wrote:
[..]
> > Well, what do you think about the extra printed information?
> > For example:
> > 
> >     <timestamp> <PID> <context> message
> > 
> > It looks straightforward to me. These information
> > might be helpful on its own. So, it might be a
> > win-win solution.
> 
> Yes, if buffering multiple lines will not be implemented, I do want
> printk context identifier field for each line. I think <PID> <context>
> part will be something like TASK#pid (if outside interrupt) or
> CPU#cpunum/#irqlevel (if inside interrupt).

well, depending on what's your aim.

it's not always printk() that causes troubles, but console_unlock().
which is busy because of printk()-s. and those are not necessarily
running on the same CPU. so if you want to have a full picture (don't
know what for) then you need to log both vprintk_emit() and
console_unlock() sides. vprintk_emit() side requires changes to
`struct printk_log', console_unlock() does not - you can just sprintf()
the required data to `text' buffer.

for example, I do the following on my PC boxes to keep track the
behaviour of printk kthread offloading.

---

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index a4e3f84ef365..ac1fd606d6c5 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2493,15 +2493,16 @@ void console_unlock(void)
                        seen_seq = log_next_seq;
                }
 
+               len = sprintf(text, "{%s/%d/%d}", current->comm,
+                               smp_processor_id(), do_cond_resched);
+
                if (console_seq < log_first_seq) {
-                       len = sprintf(text, "** %u printk messages dropped ** ",
+                       len += sprintf(text + len, "** %u printk messages dropped ** ",
                                      (unsigned)(log_first_seq - console_seq));
 
                        /* messages are gone, move to first one */
                        console_seq = log_first_seq;
                        console_idx = log_first_idx;
-               } else {
-                       len = 0;
                }
 skip:
                if (did_offload || console_seq == log_next_seq)

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-09-04  5:22                           ` Sergey Senozhatsky
  2017-09-04  5:41                             ` Joe Perches
@ 2017-09-05 14:54                             ` Steven Rostedt
  2017-09-06  2:14                               ` Sergey Senozhatsky
  2017-09-06  2:36                               ` Linus Torvalds
  1 sibling, 2 replies; 94+ messages in thread
From: Steven Rostedt @ 2017-09-05 14:54 UTC (permalink / raw)
  To: Sergey Senozhatsky
  Cc: Linus Torvalds, Joe Perches, Sergey Senozhatsky, Pavel Machek,
	Petr Mladek, Jan Kara, Andrew Morton, Jiri Slaby, Andreas Mohr,
	Tetsuo Handa, Linux Kernel Mailing List

On Mon, 4 Sep 2017 14:22:46 +0900
Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> wrote:

> like I said in another email, printk-safe buffer
> is per-CPU and is also used for actual printk-safe, hence it must be
> used with local IRQs disabled when we "borrow" the buffer for pr_line
> (disabled preemption is not enough due to possible IRQ printk-safe
> print out). this can be a bit annoying.

You can do what I did with trace_printk(). I have a buffer per context.
Then you only need to use preempt_disable() to do the print. That is,
trace_printk() has 4 buffers:

 1. Normal context
 2. softirq context
 3. irq context
 4. NMI context

It determines which context it is in, disables preemption, and uses the
corresponding buffer. This way I don't need to worry about being
preempted by an interrupt or NMI.

Grant it, it does make the memory needed 4x bigger.

I have an array of 4 buffers, and the following code:

static char *get_trace_buf(void)
{
	struct trace_buffer_struct *buffer = this_cpu_ptr(trace_percpu_buffer);

	if (!buffer || buffer->nesting >= 4)
		return NULL;

	return &buffer->buffer[buffer->nesting++][0];
}

Hmm, I probably need to add a "barrier()" before the return, or use a
this_cpu_inc() on nesting. As long as the nesting variable is updated
before the return of the buffer being used, then everything is fine.
Because we have:

static void put_trace_buf(void)
{
	this_cpu_dec(trace_percpu_buffer->nesting);
}

And anything that preempts this call will have returned it back to its
original state before returning.

-- Steve

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-09-05 14:54                             ` Steven Rostedt
@ 2017-09-06  2:14                               ` Sergey Senozhatsky
  2017-09-06  2:36                               ` Linus Torvalds
  1 sibling, 0 replies; 94+ messages in thread
From: Sergey Senozhatsky @ 2017-09-06  2:14 UTC (permalink / raw)
  To: Steven Rostedt
  Cc: Sergey Senozhatsky, Linus Torvalds, Joe Perches,
	Sergey Senozhatsky, Pavel Machek, Petr Mladek, Jan Kara,
	Andrew Morton, Jiri Slaby, Andreas Mohr, Tetsuo Handa,
	Linux Kernel Mailing List

On (09/05/17 10:54), Steven Rostedt wrote:
> On Mon, 4 Sep 2017 14:22:46 +0900
> Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> wrote:
> 
> > like I said in another email, printk-safe buffer
> > is per-CPU and is also used for actual printk-safe, hence it must be
> > used with local IRQs disabled when we "borrow" the buffer for pr_line
> > (disabled preemption is not enough due to possible IRQ printk-safe
> > print out). this can be a bit annoying.
> 
> You can do what I did with trace_printk(). I have a buffer per context.
> Then you only need to use preempt_disable() to do the print. That is,
> trace_printk() has 4 buffers:
> 
>  1. Normal context
>  2. softirq context
>  3. irq context
>  4. NMI context

thanks. looks interesting.

> It determines which context it is in, disables preemption, and uses the
> corresponding buffer. This way I don't need to worry about being
> preempted by an interrupt or NMI.
> 
> Grant it, it does make the memory needed 4x bigger.

yep. that's a concern. buffered printk must come with a sound number
of users in this case. otherwise people will just see a massive bump
(x2) in memory usage for no particular reason.

> I have an array of 4 buffers, and the following code:
> 
> static char *get_trace_buf(void)
> {
> 	struct trace_buffer_struct *buffer = this_cpu_ptr(trace_percpu_buffer);
> 
> 	if (!buffer || buffer->nesting >= 4)
> 		return NULL;
> 
> 	return &buffer->buffer[buffer->nesting++][0];
> }
> 
> Hmm, I probably need to add a "barrier()" before the return, or use a
> this_cpu_inc() on nesting. As long as the nesting variable is updated
> before the return of the buffer being used, then everything is fine.
> Because we have:
> 
> static void put_trace_buf(void)
> {
> 	this_cpu_dec(trace_percpu_buffer->nesting);
> }
> 
> And anything that preempts this call will have returned it back to its
> original state before returning.

there is a tiny-tiny-tiny chance of losing some very specific messages
from the top most context. consider the following
	trace_printk("fat fingers %o\n", 100);

from the NMI (nesting 3) context. vscnprintf() must

	WARN_ONCE(1, "Unsupported flags modifier: %c\n", fmt[1]);

which will be lost - we are above the nesting limit buffer->nesting >= 4.
// vscnprintf()->... has several more recursion entry points.

	-ss

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-09-05 14:54                             ` Steven Rostedt
  2017-09-06  2:14                               ` Sergey Senozhatsky
@ 2017-09-06  2:36                               ` Linus Torvalds
  1 sibling, 0 replies; 94+ messages in thread
From: Linus Torvalds @ 2017-09-06  2:36 UTC (permalink / raw)
  To: Steven Rostedt
  Cc: Sergey Senozhatsky, Joe Perches, Sergey Senozhatsky,
	Pavel Machek, Petr Mladek, Jan Kara, Andrew Morton, Jiri Slaby,
	Andreas Mohr, Tetsuo Handa, Linux Kernel Mailing List

On Tue, Sep 5, 2017 at 7:54 AM, Steven Rostedt <rostedt@goodmis.org> wrote:
> You can do what I did with trace_printk(). I have a buffer per context.
> Then you only need to use preempt_disable() to do the print. That is,
> trace_printk() has 4 buffers:
>
>  1. Normal context
>  2. softirq context
>  3. irq context
>  4. NMI context

This is exactly what Tetsuo's code did (except he also added the
current thread context), and I already told people once in this thread
why that doesn't work.

It may be fine if you want to do CPU tracing, but it's not acceptable
for the whole line buffering.

If I'm printing out bytes of a hex buffer, and I have a bug, and take
a page fault, the context above doesn't change.

But I sure as #%!Ing hell don't want the page fault information
buffered with my hex bytes.  They share no context at all.

So no. Stop this idiotic "implicit context". Get that disease off your
brain. It's wrong.

Either you guys are happy with the current line buffering, or you do
it with an explicit buffer context. No ifs, buts or idiotic context
markers.

                 Linus

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-09-05 13:42                                   ` Sergey Senozhatsky
@ 2017-09-06  7:55                                     ` Petr Mladek
  2017-09-17  6:26                                       ` Sergey Senozhatsky
  0 siblings, 1 reply; 94+ messages in thread
From: Petr Mladek @ 2017-09-06  7:55 UTC (permalink / raw)
  To: Sergey Senozhatsky
  Cc: Joe Perches, Steven Rostedt, Linus Torvalds, Pavel Machek,
	Sergey Senozhatsky, Jan Kara, Andrew Morton, Jiri Slaby,
	Andreas Mohr, Tetsuo Handa, Linux Kernel Mailing List

On Tue 2017-09-05 22:42:28, Sergey Senozhatsky wrote:
> On (09/05/17 14:21), Petr Mladek wrote:
> [..]
> > > that's why I want buffered printk to re-use the printk-safe buffer
> > > on that particular CPU [ if buffered printk will ever land ].
> > > printk-safe buffer is not allocated on stack, or kmalloc-ed for
> > > temp usafe, and, more importantly, we flush it from panic().
> > > 
> > > and I'm not sure that lost messages due to missing panic flush()
> > > can really be an option even for a single cont line buffer. well,
> > > may be it can. printk has a sort of guarantee that messages will
> > > be at some well known location when pr_foo or printk function
> > > returns. buffered printk kills it. and I don't want to have
> > > several "flavors" of printk. printk-safe buffer seems to be the
> > > way to preserve that guarantee.
> > 
> > But the well known locations would help only when they are flushed
> > in panic() or when a crashdump is created. They do not help
> > in other cases, especially where there is a sudden death.
> 
> if the system locked up and there is no panic()->flush_on_panic(),
> no console_unlock(), crashdump, no nothing - then even having
> messages in the logbuf is probably not really helpful. you can't
> reach them anyway :)
> so yes, I'm speaking here about the cases when we flush_on_panic()
> or/and generate crash dump.

Why are we that much paranoid about the locked up system when
discussing the console handling offload (printk kthread)?
Why should we be more relaxed when talking about pushing
messages from extra buffers?


> > There are many fears that printk offloading does not have enough
> > guarantees to actually happen. IMHO, there must be similar fears
> > that the messages in a temporary buffer will never get flushed.
> > 
> > And there are more risks with this approach:
> > 
> >   + soft-lockups caused by disabled preemption; we would
> >     need this to stay on the same CPU and use the same buffer
> 
> well, yes. like any control path that disables IRQs there are
> rules to follow. so printk-safe based solution has limitations.
> I mentioned them probably every time I speak about printk-safe
> buffering. but those limitations come with a bonus - flush on
> panic and well known location of the messages.
> 
> one thing to notice, is that
> printk-safe is usually faster than printk() or at least as fast as
> the fastest printk() path. because, unlike printk, it does not take
> spin on the logbuf lock; it does not console_trylock(), it does not
> do console_unlock().
> 
> 
> >   + broken preempt-count and missing message when one forgets
> >     to close the buffered section or do it twice
> 
> yes, coding errors are possible.
> 
> 
> >   + lost messages because a per-CPU buffer size limitations
> 
> which is true for any type of buffers. including logbuf. and
> stack allocated buffers, any buffer. printk-safe buffer is at
> least much-much bigger than any stack allocated buffer.
> 
> 
> >   + races in printk_safe() that is not recursions safe
> >
> >   + not to say the problems mentioned by Linus as reply
> >     to the Tetsuo's proposal, see
> > https://lkml.kernel.org/r/CA+55aFx+5R-vFQfr7+Ok9Yrs2adQ2Ma4fz+S6nCyWHY_-2mrmw@mail.gmail.com
> 
> like "limited in where you can actually expect buffering to happen"?
> 
> sure. it does not come for free, it's not all beautiful and shiny.

It is great that we see the risks and limitations.

> 
> [..]
> > I wonder if all this is worth the effort, complexity, and risk.
> > We are talking about cosmetic problems after all.
> 
> the thing about printk-safe buffering is that _mostly_ everything
> is already in the kernel. especially if we talk about single cont
> line buffering. just add public API printk_buffering_begin() and
> printk_buffering_end() that will __printk_safe_enter() and
> __printk_safe_exit(). and that's it. unless I'm missing something.
> 
> but I'm not super eager to have printk-safe based buffering.
> that's why I never posted a patch set. this approach has its
> limitations.

Ah, I am happy to read this. From the previous mails,
I got the feeling that you were eager to go this way.

I personally do not feel comfortable with taking all the risks
and limitations just to avoid mixed messages.

To be more precise. I am more and more pessimistic about
getting a safe buffer-based solution for multiple lines.

Well, it might make some sense for continuous lines. The
entire line should get printed within few lines of code
and limited time. Otherwise people could hardly expect
to see the pieces together. Then all the above risks and
limitations might be small and acceptable.


> > Well, what do you think about the extra printed information?
> > For example:
> > 
> >     <timestamp> <PID> <context> message
> > 
> > It looks straightforward to me. These information
> > might be helpful on its own. So, it might be a
> > win-win solution.
> 
> hm... don't know. frankly, I never found PID useful. I mostly look
> at the serial logs postmortem. so lines
> 	12231 foo
> 	21331 bar
> 
> are not much better than just
> 	foo
> 	bar

Sure, the main intention is to allow greping.


> I prepend every line with the CPU number that has printk()-ed it.
> and that's helpful because one can grep and filter out messages
> from other CPUs. it's quite OK thing to have given that messages
> can be really mixed sometimes.
> 
> so adding extra information to `struct printk_log' could be helpful.
> I think we had this discussion before and you didn't want to change
> the size of `struct printk_log' because that might break gdb/crash/etc
> user space tools. has it changed?

Yup, there should be a serious reason to change 'struct printk_log'.
I am not sure if this is the case. But I am sure that there will
be need to change the structure sooner or later.

Anyway, it seems that we will need to update all the tools
for the different time stamps, see
https://lkml.kernel.org/r/1504613201-23868-1-git-send-email-prarit@redhat.com
Then we will be more clever how painful it is.


> may be we can #ifdef CONFIG_PRINTK_ABC them.

I agree that this kind of change should be optional.

Best Regards,
Petr

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-08-30  5:37                               ` Sergey Senozhatsky
@ 2017-09-08 10:18                                 ` Pavel Machek
  0 siblings, 0 replies; 94+ messages in thread
From: Pavel Machek @ 2017-09-08 10:18 UTC (permalink / raw)
  To: Sergey Senozhatsky
  Cc: Joe Perches, Steven Rostedt, Linus Torvalds, Sergey Senozhatsky,
	Petr Mladek, Jan Kara, Andrew Morton, Jiri Slaby, Andreas Mohr,
	Tetsuo Handa, Linux Kernel Mailing List

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

On Wed 2017-08-30 14:37:34, Sergey Senozhatsky wrote:
> On (08/29/17 19:58), Joe Perches wrote:
> > > > 
> > > > Why?
> > > > 
> > > > What's wrong with a simple printk?
> > > > It'd still do a log_store.
> > > 
> > > sure, it will. but in separate logbuf entries, and between two
> > > consequent printk calls on the same CPU a lot of stuff can happen:
> > 
> > I think you don't quite understand how this would work.
> > The idea is that the entire concatenated bit would be emitted
> > in one go.
> 
> may be :)
> 
> I was thinking about the way to make it work in similar way with
> printk-safe/printk-nmi. basically seq buffer should hold both
> continuation and "normal" lines, IMHO. when we emit the buffer
> we do something like this
> 
> 	/* Print line by line. */
> 	while (c < end) {
> 		if (*c == '\n') {
> 			printk_safe_flush_line(start, c - start + 1);
> 			start = ++c;
> 			header = true;
> 			continue;
> 		}
> 
> 		/* Handle continuous lines or missing new line. */
> 		if ((c + 1 < end) && printk_get_level(c)) {
> 			if (header) {
> 				c = printk_skip_level(c);
> 				continue;
> 			}
> 
> 			printk_safe_flush_line(start, c - start);
> 			start = c++;
> 			header = true;
> 			continue;
> 		}
> 
> 		header = false;
> 		c++;
> 	}
> 
> except that instead of printk_safe_flush_line() we will call log_store()
> and the whole loop will be under logbuf_lock.
> 
> for that to work, we need API to require header/loglevel etc for every
> message. so the use case can look like this:
> 
> 	init_printk_buffer(&buf);
> 	print_line(&buf, KERN_ERR "Oops....\n");
> 
> 	print_line(&buf, KERN_ERR "continuation line: foo");
> 	print_line(&buf, KERN_CONT "bar");
> 	print_line(&buf, KERN_CONT "baz\n");
> 	...
> 
> 	print_line(&buf, KERN_ERR "....\n");
> 	...
> 	print_line(&buf, KERN_ERR "--- end of oops ---\n");
> 	emit_printk_buffer(&buf);
> 
> so that not only concatenated continuation lines will be handled,
> but also more complex things. like backtraces or whatever someone
> might want to handle.

For oopses... please don't. It is quite important that Oops goes out
"as soon as possible". I have seen oopses cut in half, etc... They are
still quite helpful.
									Pavel
-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 181 bytes --]

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-09-06  7:55                                     ` Petr Mladek
@ 2017-09-17  6:26                                       ` Sergey Senozhatsky
  2017-09-17  9:27                                         ` Sergey Senozhatsky
  2017-09-17 15:35                                         ` Linus Torvalds
  0 siblings, 2 replies; 94+ messages in thread
From: Sergey Senozhatsky @ 2017-09-17  6:26 UTC (permalink / raw)
  To: Petr Mladek
  Cc: Sergey Senozhatsky, Joe Perches, Steven Rostedt, Linus Torvalds,
	Pavel Machek, Sergey Senozhatsky, Jan Kara, Andrew Morton,
	Jiri Slaby, Andreas Mohr, Tetsuo Handa,
	Linux Kernel Mailing List

On (09/06/17 09:55), Petr Mladek wrote:
[..]
> > but I'm not super eager to have printk-safe based buffering.
> > that's why I never posted a patch set. this approach has its
> > limitations.
> 
> Ah, I am happy to read this. From the previous mails,
> I got the feeling that you were eager to go this way.

naaah, not really :)

[..]
> > I prepend every line with the CPU number that has printk()-ed it.
> > and that's helpful because one can grep and filter out messages
> > from other CPUs. it's quite OK thing to have given that messages
> > can be really mixed sometimes.
> > 
> > so adding extra information to `struct printk_log' could be helpful.
> > I think we had this discussion before and you didn't want to change
> > the size of `struct printk_log' because that might break gdb/crash/etc
> > user space tools. has it changed?
> 
> Yup, there should be a serious reason to change 'struct printk_log'.
> I am not sure if this is the case. But I am sure that there will
> be need to change the structure sooner or later.
> 
> Anyway, it seems that we will need to update all the tools
> for the different time stamps, see
> https://lkml.kernel.org/r/1504613201-23868-1-git-send-email-prarit@redhat.com
> Then we will be more clever how painful it is.
> 
> 
> > may be we can #ifdef CONFIG_PRINTK_ABC them.

so... I think we don't have to update 'struct printk_log'. we can store
that "extended data" at the beginning of every message, right after the
prefix.

NOTE:

below is a very-very quick hack. so quick, that it has known problems.
- the code does not handle !PREFIX messages (like printk("foo")).
  but I guess we can come up with a solution here.
- and printk_vscnprintf() should have that CONFIG_PRINTK_ABC,
  which is missing in the code below.


dmesg looks like this

[    3.338129] [ext: kworker/3:2/3] input: ETPS/2 Elantech Touchpad as /devices/platform/i8042/serio1/input/input7
[    3.340653] [ext: systemd-udevd/0] mousedev: PS/2 mouse device common for all mice
[    5.554184] [ext: swapper/0/0] random: crng init done
[   33.410639] [ext: wpa_supplicant/6] IPv6: ADDRCONF(NETDEV_UP): wlp2s0: link is not ready
[   36.812187] [ext: kworker/u16:5/1] wlp2s0: associated
[   36.812231] [ext: kworker/1:1/1] IPv6: ADDRCONF(NETDEV_CHANGE): wlp2s0: link becomes ready



if we will ever decide to add any sort of "extended data" to every
message, then may be we can do it this way?

---

 kernel/printk/printk.c | 31 ++++++++++++++++++++++++++++++-
 1 file changed, 30 insertions(+), 1 deletion(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index a64c52c19b03..d7380cb70fb5 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1936,6 +1936,35 @@ static size_t log_output(int facility, int level, enum log_flags lflags, const c
 	return log_store(facility, level, lflags, 0, dict, dictlen, text, text_len);
 }
 
+static size_t printk_vscnprintf(char *text, size_t text_sz,
+				const char *fmt, va_list args)
+{
+	size_t printed = 0;
+	bool do_prefix = false;
+
+	if (fmt[0] == KERN_SOH_ASCII) {
+		text[0] = fmt[0];
+		text[1] = fmt[1];
+
+		if (fmt[1] != 'c')
+			do_prefix = true;
+
+		fmt += 2;
+		printed = 2;
+	}
+
+	if (do_prefix) {
+		printed += snprintf(text + printed,
+				    text_sz - printed,
+				    "[ext: %s/%d] ",
+				    current->comm,
+				    smp_processor_id());
+	}
+
+	printed += vscnprintf(text + printed, text_sz - printed, fmt, args);
+	return printed;
+}
+
 asmlinkage int vprintk_emit(int facility, int level,
 			    const char *dict, size_t dictlen,
 			    const char *fmt, va_list args)
@@ -1962,7 +1991,7 @@ asmlinkage int vprintk_emit(int facility, int level,
 	 * The printf needs to come first; we need the syslog
 	 * prefix which might be passed-in as a parameter.
 	 */
-	text_len = vscnprintf(text, sizeof(textbuf), fmt, args);
+	text_len = printk_vscnprintf(text, sizeof(textbuf), fmt, args);
 
 	/* mark and strip a trailing newline */
 	if (text_len && text[text_len-1] == '\n') {
 

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-09-17  6:26                                       ` Sergey Senozhatsky
@ 2017-09-17  9:27                                         ` Sergey Senozhatsky
  2017-09-17 15:35                                         ` Linus Torvalds
  1 sibling, 0 replies; 94+ messages in thread
From: Sergey Senozhatsky @ 2017-09-17  9:27 UTC (permalink / raw)
  To: Petr Mladek
  Cc: Sergey Senozhatsky, Sergey Senozhatsky, Joe Perches,
	Steven Rostedt, Linus Torvalds, Pavel Machek, Jan Kara,
	Andrew Morton, Jiri Slaby, Andreas Mohr, Tetsuo Handa,
	Linux Kernel Mailing List

On (09/17/17 15:26), Sergey Senozhatsky wrote:
[..]
> > Anyway, it seems that we will need to update all the tools
> > for the different time stamps, see
> > https://lkml.kernel.org/r/1504613201-23868-1-git-send-email-prarit@redhat.com
> > Then we will be more clever how painful it is.

may be we can store that "really helpful different timestamps"
in "extended data"? IOW, as part of message text?

	-ss

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-09-17  6:26                                       ` Sergey Senozhatsky
  2017-09-17  9:27                                         ` Sergey Senozhatsky
@ 2017-09-17 15:35                                         ` Linus Torvalds
  2017-09-18  0:46                                           ` Sergey Senozhatsky
  1 sibling, 1 reply; 94+ messages in thread
From: Linus Torvalds @ 2017-09-17 15:35 UTC (permalink / raw)
  To: Sergey Senozhatsky
  Cc: Petr Mladek, Sergey Senozhatsky, Joe Perches, Steven Rostedt,
	Pavel Machek, Jan Kara, Andrew Morton, Jiri Slaby, Andreas Mohr,
	Tetsuo Handa, Linux Kernel Mailing List

On Sat, Sep 16, 2017 at 11:26 PM, Sergey Senozhatsky
<sergey.senozhatsky@gmail.com> wrote:
>
> so... I think we don't have to update 'struct printk_log'. we can store
> that "extended data" at the beginning of every message, right after the
> prefix.

No, we really can't. That just means that all the tools would have to
be changed to get the normal messages without the extra crud. And
since it will have lost the difference, that's not even easy to do.

So this is exactly the wrong way around.

If people want to see the extra data, it really should be extra data
that you can get with a new interface from the kernel logs. Not a
"let's just a add it to all lines and make every line uglier and
harder to read.

              Linus

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-09-17 15:35                                         ` Linus Torvalds
@ 2017-09-18  0:46                                           ` Sergey Senozhatsky
  2017-09-18  2:22                                             ` Joe Perches
  0 siblings, 1 reply; 94+ messages in thread
From: Sergey Senozhatsky @ 2017-09-18  0:46 UTC (permalink / raw)
  To: Linus Torvalds
  Cc: Sergey Senozhatsky, Petr Mladek, Sergey Senozhatsky, Joe Perches,
	Steven Rostedt, Pavel Machek, Jan Kara, Andrew Morton,
	Jiri Slaby, Andreas Mohr, Tetsuo Handa,
	Linux Kernel Mailing List

Hello Linus,

On (09/17/17 08:35), Linus Torvalds wrote:
> On Sat, Sep 16, 2017 at 11:26 PM, Sergey Senozhatsky
> <sergey.senozhatsky@gmail.com> wrote:
> >
> > so... I think we don't have to update 'struct printk_log'. we can store
> > that "extended data" at the beginning of every message, right after the
> > prefix.
> 
> No, we really can't. That just means that all the tools would have to
> be changed to get the normal messages without the extra crud. And
> since it will have lost the difference, that's not even easy to do.

well, that extra crud is meant to be there only when people explicitly
enable CONFIG_PRINTK_ADD_EXTRA_CRUD_PLEASE. so it's a debugging option.


> So this is exactly the wrong way around.
> 
> If people want to see the extra data, it really should be extra data
> that you can get with a new interface from the kernel logs. Not a
> "let's just a add it to all lines and make every line uglier and
> harder to read.

there is another reason why I think that, yes, we probably better do
it some other way. and the reason is that not every message that looks
like !PREFIX (does not start with KERN_SOH_ASCII) is _actually_ a
!PREFIX message. the normal/usual way is to have something like

	printk(KERN_SOH_ASCII %d " foo bar / %s %s\n", "foo", "bar");

but some messages look like

	printk("%s", KERN_SOH_ASCII %d "foo bar\n");

so we end up having a "normal" message with KERN_SOH_ASCII %d at
offsets 0 and 1 in the resulting text, but only after we do vscnprintf()
in vprintk_emit(). so the proposed _pre-processing_ is complicated.
post-processing -- the one we do in vprintk_emit() -- is still simple.


that's why last night I thought that may be we can do something more
radical - double the number of logbuf lines. IOW, every time we do

	log_store(facility, level, lflags, 0, dict, dictlen, text, text_len)

we also will do

	static char ext_data[...];

	size_t ext_sz = sprintf(ext_data, .....);
	log_store(facility, level, lflags, 0, dict, dictlen, ext_data, ext_sz);

so every message will now have "extra message" before (or after) it. we
do log_store() under logbuf lock, so no other messages should appear
(um, hopefully). every extra message will contain "[extra:" text, so it'll
be possible to filter it out... but, once again, the extra stuff is printed
only when people ask for it.


we are currently looking at
	lkml.kernel.org/r/1504613201-23868-1-git-send-email-prarit@redhat.com

which will definitely break some user space tools (well, if enabled in
.config); so I thought that may be that "helpful" timestamp can go as
extra payload.

p.s.
while I'm not entire sold on the whole timestamps in printk help
resolve issues thing. first, printk() can spin on logbuf lock before
it will read the timestamp. second, between
printk()->va_start->vprintk_func->{...this_cpu_read...}->vprintk_emit->logbuf_lock->...

and printk_get_ts() many things can happen - irq, preemption, etc. - so
timestamp that we take under ->logbuf_lock is of somewhat questionable
accurateness.

	-ss

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-09-18  0:46                                           ` Sergey Senozhatsky
@ 2017-09-18  2:22                                             ` Joe Perches
  2017-09-18  2:41                                               ` Sergey Senozhatsky
  0 siblings, 1 reply; 94+ messages in thread
From: Joe Perches @ 2017-09-18  2:22 UTC (permalink / raw)
  To: Sergey Senozhatsky, Linus Torvalds
  Cc: Sergey Senozhatsky, Petr Mladek, Steven Rostedt, Pavel Machek,
	Jan Kara, Andrew Morton, Jiri Slaby, Andreas Mohr, Tetsuo Handa,
	Linux Kernel Mailing List

On Mon, 2017-09-18 at 09:46 +0900, Sergey Senozhatsky wrote:
> there is another reason why I think that, yes, we probably better do
> it some other way. and the reason is that not every message that looks
> like !PREFIX (does not start with KERN_SOH_ASCII) is _actually_ a
> !PREFIX message. the normal/usual way is to have something like
> 
> 	printk(KERN_SOH_ASCII %d " foo bar / %s %s\n", "foo", "bar");
> 
> but some messages look like
> 
> 	printk("%s", KERN_SOH_ASCII %d "foo bar\n");

There are no messages that look like that.

There are 2 entries somewhat like that though

net/bridge/netfilter/ebt_log.c: printk(KERN_SOH "%c%s IN=%s OUT=%s MAC source = %pM MAC dest = %pM proto = 0x%04x",
net/netfilter/nf_log_common.c:  nf_log_buf_add(m, KERN_SOH "%c%sIN=%s OUT=%s ",

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-09-18  2:22                                             ` Joe Perches
@ 2017-09-18  2:41                                               ` Sergey Senozhatsky
  2017-09-18  2:45                                                 ` Joe Perches
  0 siblings, 1 reply; 94+ messages in thread
From: Sergey Senozhatsky @ 2017-09-18  2:41 UTC (permalink / raw)
  To: Joe Perches
  Cc: Sergey Senozhatsky, Linus Torvalds, Sergey Senozhatsky,
	Petr Mladek, Steven Rostedt, Pavel Machek, Jan Kara,
	Andrew Morton, Jiri Slaby, Andreas Mohr, Tetsuo Handa,
	Linux Kernel Mailing List

On (09/17/17 19:22), Joe Perches wrote:
> On Mon, 2017-09-18 at 09:46 +0900, Sergey Senozhatsky wrote:
> > there is another reason why I think that, yes, we probably better do
> > it some other way. and the reason is that not every message that looks
> > like !PREFIX (does not start with KERN_SOH_ASCII) is _actually_ a
> > !PREFIX message. the normal/usual way is to have something like
> > 
> > 	printk(KERN_SOH_ASCII %d " foo bar / %s %s\n", "foo", "bar");
> > 
> > but some messages look like
> > 
> > 	printk("%s", KERN_SOH_ASCII %d "foo bar\n");
> 
> There are no messages that look like that.
> 
> There are 2 entries somewhat like that though
> 
> net/bridge/netfilter/ebt_log.c: printk(KERN_SOH "%c%s IN=%s OUT=%s MAC source = %pM MAC dest = %pM proto = 0x%04x",
> net/netfilter/nf_log_common.c:  nf_log_buf_add(m, KERN_SOH "%c%sIN=%s OUT=%s ",

take a look at ACPI acpi_os_vprintf(). for instance.

	-ss

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-09-18  2:41                                               ` Sergey Senozhatsky
@ 2017-09-18  2:45                                                 ` Joe Perches
  2017-09-18  2:55                                                   ` Sergey Senozhatsky
  0 siblings, 1 reply; 94+ messages in thread
From: Joe Perches @ 2017-09-18  2:45 UTC (permalink / raw)
  To: Sergey Senozhatsky
  Cc: Linus Torvalds, Sergey Senozhatsky, Petr Mladek, Steven Rostedt,
	Pavel Machek, Jan Kara, Andrew Morton, Jiri Slaby, Andreas Mohr,
	Tetsuo Handa, Linux Kernel Mailing List

On Mon, 2017-09-18 at 11:41 +0900, Sergey Senozhatsky wrote:
> On (09/17/17 19:22), Joe Perches wrote:
> > On Mon, 2017-09-18 at 09:46 +0900, Sergey Senozhatsky wrote:
> > > there is another reason why I think that, yes, we probably better do
> > > it some other way. and the reason is that not every message that looks
> > > like !PREFIX (does not start with KERN_SOH_ASCII) is _actually_ a
> > > !PREFIX message. the normal/usual way is to have something like
> > > 
> > > 	printk(KERN_SOH_ASCII %d " foo bar / %s %s\n", "foo", "bar");
> > > 
> > > but some messages look like
> > > 
> > > 	printk("%s", KERN_SOH_ASCII %d "foo bar\n");
> > 
> > There are no messages that look like that.
> > 
> > There are 2 entries somewhat like that though
> > 
> > net/bridge/netfilter/ebt_log.c: printk(KERN_SOH "%c%s IN=%s OUT=%s MAC source = %pM MAC dest = %pM proto = 0x%04x",
> > net/netfilter/nf_log_common.c:  nf_log_buf_add(m, KERN_SOH "%c%sIN=%s OUT=%s ",
> 
> take a look at ACPI acpi_os_vprintf(). for instance.

I've looked.

Try git grep KERN_SOH.

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-09-18  2:45                                                 ` Joe Perches
@ 2017-09-18  2:55                                                   ` Sergey Senozhatsky
  2017-09-18  3:07                                                     ` Joe Perches
  0 siblings, 1 reply; 94+ messages in thread
From: Sergey Senozhatsky @ 2017-09-18  2:55 UTC (permalink / raw)
  To: Joe Perches
  Cc: Sergey Senozhatsky, Linus Torvalds, Sergey Senozhatsky,
	Petr Mladek, Steven Rostedt, Pavel Machek, Jan Kara,
	Andrew Morton, Jiri Slaby, Andreas Mohr, Tetsuo Handa,
	Linux Kernel Mailing List

On (09/17/17 19:45), Joe Perches wrote:
[..]
> > take a look at ACPI acpi_os_vprintf(). for instance.
> 
> I've looked.

I don't get your point.

#define ACPI_MSG_ERROR          KERN_ERR "ACPI Error: "
#define ACPI_MSG_EXCEPTION      KERN_ERR "ACPI Exception: "
#define ACPI_MSG_WARNING        KERN_WARNING "ACPI Warning: "
#define ACPI_MSG_INFO           KERN_INFO "ACPI: "

so when we do

	acpi_os_printf(ACPI_MSG_WARNING "%s: ", pathname);

we end up with

	printk("%s",  KERN_WARNING "ACPI Warning: %%pathname%%");

note how acpi_os_vprintf() calls printk_get_level() _on_ the
buffer is passes to

	printk("%s", buffer)

because KERN_WARNING is part of the buffer, not the fmt.

there are also other examples that do similar things.


> Try git grep KERN_SOH.

what for?

	-ss

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-09-18  2:55                                                   ` Sergey Senozhatsky
@ 2017-09-18  3:07                                                     ` Joe Perches
  2017-09-18  4:42                                                       ` Sergey Senozhatsky
  0 siblings, 1 reply; 94+ messages in thread
From: Joe Perches @ 2017-09-18  3:07 UTC (permalink / raw)
  To: Sergey Senozhatsky
  Cc: Linus Torvalds, Sergey Senozhatsky, Petr Mladek, Steven Rostedt,
	Pavel Machek, Jan Kara, Andrew Morton, Jiri Slaby, Andreas Mohr,
	Tetsuo Handa, Linux Kernel Mailing List

On Mon, 2017-09-18 at 11:55 +0900, Sergey Senozhatsky wrote:
> Try git grep KERN_SOH.
> 
> what for?

Did you read your own email?

>	printk(KERN_SOH_ASCII %d " foo bar / %s %s\n", "foo", "bar");

_nothing_ looks like that.

It wouldn't even compile.

^ permalink raw reply	[flat|nested] 94+ messages in thread

* Re: printk: what is going on with additional newlines?
  2017-09-18  3:07                                                     ` Joe Perches
@ 2017-09-18  4:42                                                       ` Sergey Senozhatsky
  0 siblings, 0 replies; 94+ messages in thread
From: Sergey Senozhatsky @ 2017-09-18  4:42 UTC (permalink / raw)
  To: Joe Perches
  Cc: Sergey Senozhatsky, Linus Torvalds, Sergey Senozhatsky,
	Petr Mladek, Steven Rostedt, Pavel Machek, Jan Kara,
	Andrew Morton, Jiri Slaby, Andreas Mohr, Tetsuo Handa,
	Linux Kernel Mailing List

On (09/17/17 20:07), Joe Perches wrote:
> On Mon, 2017-09-18 at 11:55 +0900, Sergey Senozhatsky wrote:
> > Try git grep KERN_SOH.
> > 
> > what for?
> 
> Did you read your own email?
> 
> >	printk(KERN_SOH_ASCII %d " foo bar / %s %s\n", "foo", "bar");
> 
> _nothing_ looks like that.

OK... got it. I obviously meant the way we treat the
prefix - KERN_SOH_ASCII and int loglevel that we store
in msg->level - and not the way the prefix actually looks
(KERN_SOH %c). I thought that was kinda clear. anyway,
the point of my email was completely different.

sorry if that confused you, or anybody else.


> It wouldn't even compile.

well, don't try to compile my emails  ;)

	-ss

^ permalink raw reply	[flat|nested] 94+ messages in thread

end of thread, other threads:[~2017-09-18  4:42 UTC | newest]

Thread overview: 94+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2017-08-15  2:56 [RFC][PATCHv5 00/13] printk: introduce printing kernel thread Sergey Senozhatsky
2017-08-15  2:56 ` [RFC][PATCHv5 01/13] printk: move printk_pending out of per-cpu Sergey Senozhatsky
2017-08-15  2:56 ` [RFC][PATCHv5 02/13] printk: introduce printing kernel thread Sergey Senozhatsky
2017-08-15  2:56 ` [RFC][PATCHv5 03/13] printk: add sync printk_emergency API Sergey Senozhatsky
2017-08-15  2:56 ` [RFC][PATCHv5 04/13] printk: add enforce_emergency parameter Sergey Senozhatsky
2017-08-15  2:56 ` [RFC][PATCHv5 05/13] printk: enable printk offloading Sergey Senozhatsky
2017-08-15  2:56 ` [RFC][PATCHv5 06/13] printk: register PM notifier Sergey Senozhatsky
2017-08-15 11:51   ` Rafael J. Wysocki
2017-08-16  7:31     ` Sergey Senozhatsky
2017-08-16 12:58       ` Rafael J. Wysocki
2017-08-17  5:55         ` Sergey Senozhatsky
2017-08-17 15:43           ` Rafael J. Wysocki
2017-08-17 23:19             ` Sergey Senozhatsky
2017-08-15  2:56 ` [RFC][PATCHv5 07/13] printk: register syscore notifier Sergey Senozhatsky
2017-08-15 11:56   ` Rafael J. Wysocki
2017-08-16  6:55     ` Sergey Senozhatsky
2017-08-16 12:59       ` Rafael J. Wysocki
2017-08-15  2:56 ` [RFC][PATCHv5 08/13] printk: set watchdog_thresh as maximum value for atomic_print_limit Sergey Senozhatsky
2017-08-15  2:56 ` [RFC][PATCHv5 09/13] printk: add auto-emergency enforcement mechanism Sergey Senozhatsky
2017-08-15  2:56 ` [RFC][PATCHv5 10/13] printk: force printk_kthread to offload printing Sergey Senozhatsky
2017-08-15  2:56 ` [RFC][PATCHv5 11/13] printk: always offload printing from user-space processes Sergey Senozhatsky
2017-08-15  2:56 ` [RFC][PATCHv5 12/13] printk: do not cond_resched() when we can offload Sergey Senozhatsky
2017-08-15  2:56 ` [RFC][PATCHv5 13/13] printk: move offloading logic to per-cpu Sergey Senozhatsky
2017-08-23  8:33 ` [RFC][PATCHv5 00/13] printk: introduce printing kernel thread Sergey Senozhatsky
2017-08-28  9:05 ` printk: what is going on with additional newlines? Pavel Machek
2017-08-28 10:28   ` Sergey Senozhatsky
2017-08-28 12:21     ` Sergey Senozhatsky
2017-08-28 12:38       ` Sergey Senozhatsky
2017-08-28 12:46       ` Pavel Machek
2017-08-29 13:40         ` Sergey Senozhatsky
2017-08-29 16:37           ` Joe Perches
2017-08-29 17:00           ` Linus Torvalds
2017-08-29 17:12             ` Linus Torvalds
2017-08-29 20:41               ` Tetsuo Handa
2017-08-29 20:51                 ` Linus Torvalds
2017-09-02  6:12                   ` Tetsuo Handa
2017-09-02 17:06                     ` Linus Torvalds
2017-08-29 23:50               ` Steven Rostedt
2017-08-29 23:59                 ` Linus Torvalds
2017-08-30  1:03                 ` Sergey Senozhatsky
2017-08-30  1:10                   ` Steven Rostedt
2017-08-30  1:51                     ` Sergey Senozhatsky
2017-08-30  1:52                     ` Joe Perches
2017-08-30  2:25                       ` Sergey Senozhatsky
2017-08-30  2:31                         ` Joe Perches
2017-08-30  2:47                           ` Sergey Senozhatsky
2017-08-30  2:58                             ` Joe Perches
2017-08-30  5:37                               ` Sergey Senozhatsky
2017-09-08 10:18                                 ` Pavel Machek
2017-09-05  9:44                             ` Petr Mladek
2017-09-05  9:59                               ` Sergey Senozhatsky
2017-09-05 12:21                                 ` Petr Mladek
2017-09-05 12:35                                   ` Tetsuo Handa
2017-09-05 14:18                                     ` Sergey Senozhatsky
2017-09-05 13:42                                   ` Sergey Senozhatsky
2017-09-06  7:55                                     ` Petr Mladek
2017-09-17  6:26                                       ` Sergey Senozhatsky
2017-09-17  9:27                                         ` Sergey Senozhatsky
2017-09-17 15:35                                         ` Linus Torvalds
2017-09-18  0:46                                           ` Sergey Senozhatsky
2017-09-18  2:22                                             ` Joe Perches
2017-09-18  2:41                                               ` Sergey Senozhatsky
2017-09-18  2:45                                                 ` Joe Perches
2017-09-18  2:55                                                   ` Sergey Senozhatsky
2017-09-18  3:07                                                     ` Joe Perches
2017-09-18  4:42                                                       ` Sergey Senozhatsky
2017-09-01 13:19                     ` Sergey Senozhatsky
2017-09-01 17:32                       ` Joe Perches
2017-09-01 20:21                         ` Linus Torvalds
2017-09-04  5:22                           ` Sergey Senozhatsky
2017-09-04  5:41                             ` Joe Perches
2017-09-05 14:54                             ` Steven Rostedt
2017-09-06  2:14                               ` Sergey Senozhatsky
2017-09-06  2:36                               ` Linus Torvalds
2017-09-04  4:30                         ` Sergey Senozhatsky
2017-09-04  5:24                           ` Sergey Senozhatsky
2017-08-29 17:33             ` Sergey Senozhatsky
2017-08-29 17:52               ` Linus Torvalds
2017-08-29 18:09                 ` Joe Perches
2017-08-30  1:07                   ` Sergey Senozhatsky
2017-08-30  0:58                 ` Sergey Senozhatsky
2017-08-29 16:48   ` Linus Torvalds
2017-08-29 17:10     ` Joe Perches
2017-08-29 17:20       ` Linus Torvalds
2017-08-29 17:33         ` Joe Perches
2017-08-29 17:36           ` Linus Torvalds
2017-08-29 17:48             ` Joe Perches
2017-08-29 20:24     ` Pavel Machek
2017-09-01  1:40       ` Sergey Senozhatsky
2017-09-01  2:04         ` Joe Perches
2017-09-01  6:59           ` Pavel Machek
2017-09-01  7:23             ` Joe Perches
2017-09-01  7:29         ` Pavel Machek
2017-09-01 11:13           ` Steven Rostedt

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.