[RFC][PATCH -next 0/2] cond_resched() some of console_trylock callers

[RFC][PATCH -next 0/2] cond_resched() some of console_trylock callers

[Sergey Senozhatsky]

Hello,

RFC (apologies for sending it during the merge window. no rush)

console_unlock() allows to cond_resched() if its caller has
set `console_may_schedule' to 1 (this functionality present
since commit 'printk: do cond_resched() between lines while
outputting to consoles').

The rules are:
-- console_lock() always sets `console_may_schedule' to 1
-- console_trylock() always sets `console_may_schedule' to 0

However, console_trylock() callers (among them is printk()) are
not necessarily executing in atomic contexts, and some of them
can cond_resched() in console_unlock(). So console_trylock()
can set `console_may_schedule' to 0 only if cond_resched() is
invalid in the current context, and set it to 1 otherwise.

Patch 0001 addresses a theoretical loss of printk messages and,
at the same time, serves as a preparation work for 0002.

Sergey Senozhatsky (2):
  printk: move can_use_console out of console_trylock_for_printk
  printk: set may_schedule for some of console_trylock callers

 kernel/printk/printk.c | 84 ++++++++++++++++++++++++--------------------------
 1 file changed, 40 insertions(+), 44 deletions(-)

-- 
2.7.0

[RFC][PATCH -next 1/2] printk: move can_use_console out of console_trylock_for_printk

[Sergey Senozhatsky]

vprintk_emit() disables preemption around console_trylock_for_printk()
and console_unlock() calls for a strong reason -- can_use_console()
check. The thing is that vprintl_emit() can be called on a CPU that
is not fully brought up yet (!cpu_online()), which potentially can
cause problems if console driver accesses per-cpu data. A console
driver can explicitly state that it's safe to call it from !online
cpu by setting CON_ANYTIME bit in console ->flags. That's why for
!cpu_online() can_use_console() iterates all the console to find out
if there is a CON_ANYTIME console, otherwise console_unlock() must be
avoided.

call_console_drivers(), called from console_cont_flush() and
console_unlock(), does the same test during for_each_console() loop.
However, we can have the following corner case. Assume that we have 2
cpus -- CPU0 is online, CPU1 is !online; and no CON_ANYTIME consoles
available.

CPU0 online                        CPU1 !online
                                 console_trylock()
                                 ...
                                 console_unlock()
                                   console_cont_flush
                                     spin_lock logbuf_lock
                                     if (!cont.len) {
                                        spin_unlock logbuf_lock
                                        return
                                     }
                                   for (;;) {
vprintk_emit
  spin_lock logbuf_lock
  log_store
  spin_unlock logbuf_lock
                                     spin_lock logbuf_lock
  !console_trylock_for_printk        msg_print_text
 return                              console_idx = log_next()
                                     console_seq++
                                     console_prev = msg->flags
                                     spin_unlock logbuf_lock

                                     call_console_drivers()
                                       for_each_console(con) {
                                         if (!cpu_online() &&
                                             !(con->flags & CON_ANYTIME))
                                                 continue;
                                         }
                                   /*
                                    * no message printed, we lost it
                                    */
vprintk_emit
  spin_lock logbuf_lock
  log_store
  spin_unlock logbuf_lock
  !console_trylock_for_printk
 return
                                   /*
                                    * go to the beginning of the loop,
                                    * find out there are new messages,
                                    * lose it
                                    */
                                   }

This patch moves can_use_console() check out of
console_trylock_for_printk(). Instead it calls it in two
non-preemptible sections:
-- console_cont_flush()
   can_use_console() call happens with spin_lock logbuf_lock
   taken and local IRQs disabled, local IRQs are not enabled
   until call_console_drivers() returns.

-- console_unlock()
   can_use_console() call happens with spin_lock logbuf_lock
   taken and local IRQs disabled, local IRQs are not enabled
   until call_console_drivers() returns.

In both cases, we need to know that call_console_drivers() call
was aborted because of !can_use_console() and we must exit
console_unlock() function.

This also lets to drop '!cpu_online() && !(con->flags & CON_ANYTIME)'
test from call_console_drivers().

At the same time this patch serves as a preparation to enable
cond_resched for 'in-direct' console_unlock() callers -- the ones
that come from vprintk_emit(). The 'direct' ones -- the ones that
do console_lock()/console_unlock() -- already can cond_resched.

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

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 7ebcfea..5cc0ce6 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1452,9 +1452,6 @@ static void call_console_drivers(int level,
 			continue;
 		if (!con->write)
 			continue;
-		if (!cpu_online(smp_processor_id()) &&
-		    !(con->flags & CON_ANYTIME))
-			continue;
 		if (con->flags & CON_EXTENDED)
 			con->write(con, ext_text, ext_len);
 		else
@@ -1500,18 +1497,6 @@ static int have_callable_console(void)
 }
 
 /*
- * Can we actually use the console at this time on this cpu?
- *
- * Console drivers may assume that per-cpu resources have been allocated. So
- * unless they're explicitly marked as being able to cope (CON_ANYTIME) don't
- * call them until this CPU is officially up.
- */
-static inline int can_use_console(unsigned int cpu)
-{
-	return cpu_online(cpu) || have_callable_console();
-}
-
-/*
  * Try to get console ownership to actually show the kernel
  * messages from a 'printk'. Return true (and with the
  * console_lock held, and 'console_locked' set) if it
@@ -1519,21 +1504,7 @@ static inline int can_use_console(unsigned int cpu)
  */
 static int console_trylock_for_printk(void)
 {
-	unsigned int cpu = smp_processor_id();
-
-	if (!console_trylock())
-		return 0;
-	/*
-	 * If we can't use the console, we need to release the console
-	 * semaphore by hand to avoid flushing the buffer. We need to hold the
-	 * console semaphore in order to do this test safely.
-	 */
-	if (!can_use_console(cpu)) {
-		console_locked = 0;
-		up_console_sem();
-		return 0;
-	}
-	return 1;
+	return console_trylock();
 }
 
 int printk_delay_msec __read_mostly;
@@ -2177,10 +2148,23 @@ int is_console_locked(void)
 	return console_locked;
 }
 
-static void console_cont_flush(char *text, size_t size)
+/*
+ * Can we actually use the console at this time on this cpu?
+ *
+ * Console drivers may assume that per-cpu resources have been allocated. So
+ * unless they're explicitly marked as being able to cope (CON_ANYTIME) don't
+ * call them until this CPU is officially up.
+ */
+static inline int can_use_console(void)
+{
+	return cpu_online(smp_processor_id()) || have_callable_console();
+}
+
+static bool console_cont_flush(char *text, size_t size)
 {
 	unsigned long flags;
 	size_t len;
+	bool ret = true;
 
 	raw_spin_lock_irqsave(&logbuf_lock, flags);
 
@@ -2195,15 +2179,21 @@ static void console_cont_flush(char *text, size_t size)
 	if (console_seq < log_next_seq && !cont.cons)
 		goto out;
 
+	if (!can_use_console()) {
+		ret = false;
+		goto out;
+	}
+
 	len = cont_print_text(text, size);
 	raw_spin_unlock(&logbuf_lock);
 	stop_critical_timings();
 	call_console_drivers(cont.level, NULL, 0, text, len);
 	start_critical_timings();
 	local_irq_restore(flags);
-	return;
+	return ret;
 out:
 	raw_spin_unlock_irqrestore(&logbuf_lock, flags);
+	return ret;
 }
 
 /**
@@ -2227,7 +2217,7 @@ void console_unlock(void)
 	static u64 seen_seq;
 	unsigned long flags;
 	bool wake_klogd = false;
-	bool do_cond_resched, retry;
+	bool do_cond_resched, retry, aborted = false;
 
 	if (console_suspended) {
 		up_console_sem();
@@ -2248,7 +2238,12 @@ void console_unlock(void)
 	console_may_schedule = 0;
 
 	/* flush buffered message fragment immediately to console */
-	console_cont_flush(text, sizeof(text));
+	if (!console_cont_flush(text, sizeof(text))) {
+		console_locked = 0;
+		up_console_sem();
+		return;
+	}
+
 again:
 	for (;;) {
 		struct printk_log *msg;
@@ -2257,6 +2252,12 @@ again:
 		int level;
 
 		raw_spin_lock_irqsave(&logbuf_lock, flags);
+
+		if (!can_use_console()) {
+			aborted = true;
+			break;
+		}
+
 		if (seen_seq != log_next_seq) {
 			wake_klogd = true;
 			seen_seq = log_next_seq;
@@ -2337,7 +2338,7 @@ skip:
 	 * flush, no worries.
 	 */
 	raw_spin_lock(&logbuf_lock);
-	retry = console_seq != log_next_seq;
+	retry = !aborted && (console_seq != log_next_seq);
 	raw_spin_unlock_irqrestore(&logbuf_lock, flags);
 
 	if (retry && console_trylock())
-- 
2.7.0

[RFC][PATCH -next 2/2] printk: set may_schedule for some of console_trylock callers

[Sergey Senozhatsky]

 console_unlock() allows to cond_resched() if its caller has
set `console_may_schedule' to 1 (this functionality present
since commit 'printk: do cond_resched() between lines while
outputting to consoles').

The rules are:
-- console_lock() always sets `console_may_schedule' to 1
-- console_trylock() always sets `console_may_schedule' to 0

However, console_trylock() callers (among them is printk()) are
not necessarily executing in atomic contexts, and some of them
can cond_resched() in console_unlock(). So console_trylock()
can set `console_may_schedule' to 0 only if cond_resched() is
invalid in the current context, and set it to 1 otherwise.

The patch also drops explicit preempt_disable()/preempt_enable()
calls in vprintk_emit().

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

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 5cc0ce6..d0f5a73 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1792,20 +1792,12 @@ asmlinkage int vprintk_emit(int facility, int level,
 	if (!in_sched) {
 		lockdep_off();
 		/*
-		 * Disable preemption to avoid being preempted while holding
-		 * console_sem which would prevent anyone from printing to
-		 * console
-		 */
-		preempt_disable();
-
-		/*
 		 * Try to acquire and then immediately release the console
 		 * semaphore.  The release will print out buffers and wake up
 		 * /dev/kmsg and syslog() users.
 		 */
 		if (console_trylock_for_printk())
 			console_unlock();
-		preempt_enable();
 		lockdep_on();
 	}
 
@@ -2138,7 +2130,10 @@ int console_trylock(void)
 		return 0;
 	}
 	console_locked = 1;
-	console_may_schedule = 0;
+	console_may_schedule = !(oops_in_progress ||
+			in_interrupt() ||
+			irqs_disabled() ||
+			in_atomic());
 	return 1;
 }
 EXPORT_SYMBOL(console_trylock);
-- 
2.7.0

[PATCH 1/2] printk: move can_use_console out of console_trylock_for_printk

[Sergey Senozhatsky]

vprintk_emit() disables preemption around console_trylock_for_printk()
and console_unlock() calls for a strong reason -- can_use_console()
check. The thing is that vprintl_emit() can be called on a CPU that
is not fully brought up yet (!cpu_online()), which potentially can
cause problems if console driver accesses per-cpu data. A console
driver can explicitly state that it's safe to call it from !online
cpu by setting CON_ANYTIME bit in console ->flags. That's why for
!cpu_online() can_use_console() iterates all the console to find out
if there is a CON_ANYTIME console, otherwise console_unlock() must be
avoided.

call_console_drivers(), called from console_cont_flush() and
console_unlock(), does the same test during for_each_console() loop.
However, we can have the following corner case. Assume that we have 2
cpus -- CPU0 is online, CPU1 is !online; and no CON_ANYTIME consoles
available.

CPU0 online                        CPU1 !online
                                 console_trylock()
                                 ...
                                 console_unlock()
                                   console_cont_flush
                                     spin_lock logbuf_lock
                                     if (!cont.len) {
                                        spin_unlock logbuf_lock
                                        return
                                     }
                                   for (;;) {
vprintk_emit
  spin_lock logbuf_lock
  log_store
  spin_unlock logbuf_lock
                                     spin_lock logbuf_lock
  !console_trylock_for_printk        msg_print_text
 return                              console_idx = log_next()
                                     console_seq++
                                     console_prev = msg->flags
                                     spin_unlock logbuf_lock

                                     call_console_drivers()
                                       for_each_console(con) {
                                         if (!cpu_online() &&
                                             !(con->flags & CON_ANYTIME))
                                                 continue;
                                         }
                                   /*
                                    * no message printed, we lost it
                                    */
vprintk_emit
  spin_lock logbuf_lock
  log_store
  spin_unlock logbuf_lock
  !console_trylock_for_printk
 return
                                   /*
                                    * go to the beginning of the loop,
                                    * find out there are new messages,
                                    * lose it
                                    */
                                   }

This patch moves can_use_console() check out of
console_trylock_for_printk(). Instead it calls it in two
non-preemptible sections:
1) console_cont_flush()
   can_use_console() call happens with spin_lock logbuf_lock
   taken and local IRQs disabled, local IRQs are not enabled
   until call_console_drivers() returns.

2) console_unlock()
   can_use_console() call happens with spin_lock logbuf_lock
   taken and local IRQs disabled, local IRQs are not enabled
   until call_console_drivers() returns.

In both cases, we need to know that call_console_drivers() call
was aborted because of !can_use_console() and we must exit
console_unlock() function.

This also lets to drop '!cpu_online() && !(con->flags & CON_ANYTIME)'
test from call_console_drivers().

At the same time this patch serves as a preparation to enable
cond_resched for 'in-direct' console_unlock() callers -- the ones
that come from vprintk_emit(). The 'direct' ones -- the ones that
do console_lock()/console_unlock() -- already can cond_resched.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
V2:
make have_callable_console() available for !PRINTK configs (lkp@intel.com)

 kernel/printk/printk.c | 101 +++++++++++++++++++++++++------------------------
 1 file changed, 51 insertions(+), 50 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 7ebcfea..ae641d7 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1452,9 +1452,6 @@ static void call_console_drivers(int level,
 			continue;
 		if (!con->write)
 			continue;
-		if (!cpu_online(smp_processor_id()) &&
-		    !(con->flags & CON_ANYTIME))
-			continue;
 		if (con->flags & CON_EXTENDED)
 			con->write(con, ext_text, ext_len);
 		else
@@ -1485,33 +1482,6 @@ static void zap_locks(void)
 }
 
 /*
- * Check if we have any console that is capable of printing while cpu is
- * booting or shutting down. Requires console_sem.
- */
-static int have_callable_console(void)
-{
-	struct console *con;
-
-	for_each_console(con)
-		if (con->flags & CON_ANYTIME)
-			return 1;
-
-	return 0;
-}
-
-/*
- * Can we actually use the console at this time on this cpu?
- *
- * Console drivers may assume that per-cpu resources have been allocated. So
- * unless they're explicitly marked as being able to cope (CON_ANYTIME) don't
- * call them until this CPU is officially up.
- */
-static inline int can_use_console(unsigned int cpu)
-{
-	return cpu_online(cpu) || have_callable_console();
-}
-
-/*
  * Try to get console ownership to actually show the kernel
  * messages from a 'printk'. Return true (and with the
  * console_lock held, and 'console_locked' set) if it
@@ -1519,21 +1489,7 @@ static inline int can_use_console(unsigned int cpu)
  */
 static int console_trylock_for_printk(void)
 {
-	unsigned int cpu = smp_processor_id();
-
-	if (!console_trylock())
-		return 0;
-	/*
-	 * If we can't use the console, we need to release the console
-	 * semaphore by hand to avoid flushing the buffer. We need to hold the
-	 * console semaphore in order to do this test safely.
-	 */
-	if (!can_use_console(cpu)) {
-		console_locked = 0;
-		up_console_sem();
-		return 0;
-	}
-	return 1;
+	return console_trylock();
 }
 
 int printk_delay_msec __read_mostly;
@@ -2177,10 +2133,38 @@ int is_console_locked(void)
 	return console_locked;
 }
 
-static void console_cont_flush(char *text, size_t size)
+/*
+ * Check if we have any console that is capable of printing while cpu is
+ * booting or shutting down. Requires console_sem.
+ */
+static int have_callable_console(void)
+{
+	struct console *con;
+
+	for_each_console(con)
+		if (con->flags & CON_ANYTIME)
+			return 1;
+
+	return 0;
+}
+
+/*
+ * Can we actually use the console at this time on this cpu?
+ *
+ * Console drivers may assume that per-cpu resources have been allocated. So
+ * unless they're explicitly marked as being able to cope (CON_ANYTIME) don't
+ * call them until this CPU is officially up.
+ */
+static inline int can_use_console(void)
+{
+	return cpu_online(smp_processor_id()) || have_callable_console();
+}
+
+static bool console_cont_flush(char *text, size_t size)
 {
 	unsigned long flags;
 	size_t len;
+	bool ret = true;
 
 	raw_spin_lock_irqsave(&logbuf_lock, flags);
 
@@ -2195,15 +2179,21 @@ static void console_cont_flush(char *text, size_t size)
 	if (console_seq < log_next_seq && !cont.cons)
 		goto out;
 
+	if (!can_use_console()) {
+		ret = false;
+		goto out;
+	}
+
 	len = cont_print_text(text, size);
 	raw_spin_unlock(&logbuf_lock);
 	stop_critical_timings();
 	call_console_drivers(cont.level, NULL, 0, text, len);
 	start_critical_timings();
 	local_irq_restore(flags);
-	return;
+	return ret;
 out:
 	raw_spin_unlock_irqrestore(&logbuf_lock, flags);
+	return ret;
 }
 
 /**
@@ -2227,7 +2217,7 @@ void console_unlock(void)
 	static u64 seen_seq;
 	unsigned long flags;
 	bool wake_klogd = false;
-	bool do_cond_resched, retry;
+	bool do_cond_resched, retry, aborted = false;
 
 	if (console_suspended) {
 		up_console_sem();
@@ -2248,7 +2238,12 @@ void console_unlock(void)
 	console_may_schedule = 0;
 
 	/* flush buffered message fragment immediately to console */
-	console_cont_flush(text, sizeof(text));
+	if (!console_cont_flush(text, sizeof(text))) {
+		console_locked = 0;
+		up_console_sem();
+		return;
+	}
+
 again:
 	for (;;) {
 		struct printk_log *msg;
@@ -2257,6 +2252,12 @@ again:
 		int level;
 
 		raw_spin_lock_irqsave(&logbuf_lock, flags);
+
+		if (!can_use_console()) {
+			aborted = true;
+			break;
+		}
+
 		if (seen_seq != log_next_seq) {
 			wake_klogd = true;
 			seen_seq = log_next_seq;
@@ -2337,7 +2338,7 @@ skip:
 	 * flush, no worries.
 	 */
 	raw_spin_lock(&logbuf_lock);
-	retry = console_seq != log_next_seq;
+	retry = !aborted && (console_seq != log_next_seq);
 	raw_spin_unlock_irqrestore(&logbuf_lock, flags);
 
 	if (retry && console_trylock())
-- 
2.7.0

Re: [RFC][PATCH -next 2/2] printk: set may_schedule for some of console_trylock callers

[Sergey Senozhatsky]

On (01/14/16 13:57), Sergey Senozhatsky wrote:
[..]
> @@ -2138,7 +2130,10 @@ int console_trylock(void)
>  		return 0;
>  	}
>  	console_locked = 1;
> -	console_may_schedule = 0;
> +	console_may_schedule = !(oops_in_progress ||
> +			in_interrupt() ||
> +			irqs_disabled() ||
> +			in_atomic());
>  	return 1;
>  }

should check rcu_preempt_depth() on preempt RCU kernels.
and in_interrupt() can be dropped, in_atomic() does
preempt_count != 0.

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

 console_unlock() allows to cond_resched() if its caller has
set `console_may_schedule' to 1 (this functionality present
since commit 'printk: do cond_resched() between lines while
outputting to consoles').

The rules are:
-- console_lock() always sets `console_may_schedule' to 1
-- console_trylock() always sets `console_may_schedule' to 0

However, console_trylock() callers (among them is printk()) are
not necessarily executing in atomic contexts, and some of them
can cond_resched() in console_unlock(). So console_trylock()
can set `console_may_schedule' to 0 only if cond_resched() is
invalid in the current context, and set it to 1 otherwise.

The patch also drops explicit preempt_disable()/preempt_enable()
calls in vprintk_emit().

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
V2: rcu_preempt_depth() on preempt RCU kernels

 kernel/printk/printk.c | 13 ++++---------
 1 file changed, 4 insertions(+), 9 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index ae641d7..5752c0e 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1777,20 +1777,12 @@ asmlinkage int vprintk_emit(int facility, int level,
 	if (!in_sched) {
 		lockdep_off();
 		/*
-		 * Disable preemption to avoid being preempted while holding
-		 * console_sem which would prevent anyone from printing to
-		 * console
-		 */
-		preempt_disable();
-
-		/*
 		 * Try to acquire and then immediately release the console
 		 * semaphore.  The release will print out buffers and wake up
 		 * /dev/kmsg and syslog() users.
 		 */
 		if (console_trylock_for_printk())
 			console_unlock();
-		preempt_enable();
 		lockdep_on();
 	}
 
@@ -2123,7 +2115,10 @@ int console_trylock(void)
 		return 0;
 	}
 	console_locked = 1;
-	console_may_schedule = 0;
+	console_may_schedule = !(oops_in_progress ||
+			irqs_disabled() ||
+			in_atomic(),
+			rcu_preempt_depth());
 	return 1;
 }
 EXPORT_SYMBOL(console_trylock);
-- 
2.7.0

Re: [RFC][PATCH -next 2/2] printk: set may_schedule for some of console_trylock callers

[Sergey Senozhatsky]

On (01/17/16 23:11), Sergey Senozhatsky wrote:
[..]
>  	console_locked = 1;
> -	console_may_schedule = 0;
> +	console_may_schedule = !(oops_in_progress ||
> +			irqs_disabled() ||
> +			in_atomic(),
				^^^^ fat fingers, obviously. ||
> +			rcu_preempt_depth());

sorry.

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

 console_unlock() allows to cond_resched() if its caller has
set `console_may_schedule' to 1 (this functionality present
since commit 'printk: do cond_resched() between lines while
outputting to consoles').

The rules are:
-- console_lock() always sets `console_may_schedule' to 1
-- console_trylock() always sets `console_may_schedule' to 0

However, console_trylock() callers (among them is printk()) are
not necessarily executing in atomic contexts, and some of them
can cond_resched() in console_unlock(). So console_trylock()
can set `console_may_schedule' to 0 only if cond_resched() is
invalid in the current context, and set it to 1 otherwise.

The patch also drops explicit preempt_disable()/preempt_enable()
calls in vprintk_emit().

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
V2: rcu_preempt_depth() on preempt RCU kernels

 kernel/printk/printk.c | 13 ++++---------
 1 file changed, 4 insertions(+), 9 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index ae641d7..9ac05e0 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1777,20 +1777,12 @@ asmlinkage int vprintk_emit(int facility, int level,
 	if (!in_sched) {
 		lockdep_off();
 		/*
-		 * Disable preemption to avoid being preempted while holding
-		 * console_sem which would prevent anyone from printing to
-		 * console
-		 */
-		preempt_disable();
-
-		/*
 		 * Try to acquire and then immediately release the console
 		 * semaphore.  The release will print out buffers and wake up
 		 * /dev/kmsg and syslog() users.
 		 */
 		if (console_trylock_for_printk())
 			console_unlock();
-		preempt_enable();
 		lockdep_on();
 	}
 
@@ -2123,7 +2115,10 @@ int console_trylock(void)
 		return 0;
 	}
 	console_locked = 1;
-	console_may_schedule = 0;
+	console_may_schedule = !(oops_in_progress ||
+			irqs_disabled() ||
+			in_atomic() ||
+			rcu_preempt_depth());
 	return 1;
 }
 EXPORT_SYMBOL(console_trylock);
-- 
2.7.0

Re: [RFC][PATCH -next 1/2] printk: move can_use_console out of console_trylock_for_printk

[Petr Mladek]

On Thu 2016-01-14 13:57:22, Sergey Senozhatsky wrote:
> vprintk_emit() disables preemption around console_trylock_for_printk()
> and console_unlock() calls for a strong reason -- can_use_console()
> check. The thing is that vprintl_emit() can be called on a CPU that
> is not fully brought up yet (!cpu_online()), which potentially can
> cause problems if console driver accesses per-cpu data. A console
> driver can explicitly state that it's safe to call it from !online
> cpu by setting CON_ANYTIME bit in console ->flags. That's why for
> !cpu_online() can_use_console() iterates all the console to find out
> if there is a CON_ANYTIME console, otherwise console_unlock() must be
> avoided.
> 
> call_console_drivers(), called from console_cont_flush() and
> console_unlock(), does the same test during for_each_console() loop.
> However, we can have the following corner case. Assume that we have 2
> cpus -- CPU0 is online, CPU1 is !online; and no CON_ANYTIME consoles
> available.
> 
> CPU0 online                        CPU1 !online
>                                  console_trylock()
>                                  ...
>                                  console_unlock()

Please, where this console_unlock() comes from? If I get this
correctly, this CPU is not online and no CON_ANYTIME console exists
=> can_use_console() fails
  => console_trylock() fails
    => console_unlock() is not called from vprintk_emit().

Best Regards,
Petr

>                                    console_cont_flush
>                                      spin_lock logbuf_lock
>                                      if (!cont.len) {
>                                         spin_unlock logbuf_lock
>                                         return
>                                      }
>                                    for (;;) {
> vprintk_emit
>   spin_lock logbuf_lock
>   log_store
>   spin_unlock logbuf_lock
>                                      spin_lock logbuf_lock
>   !console_trylock_for_printk        msg_print_text
>  return                              console_idx = log_next()
>                                      console_seq++
>                                      console_prev = msg->flags
>                                      spin_unlock logbuf_lock
> 
>                                      call_console_drivers()
>                                        for_each_console(con) {
>                                          if (!cpu_online() &&
>                                              !(con->flags & CON_ANYTIME))
>                                                  continue;
>                                          }
>                                    /*
>                                     * no message printed, we lost it
>                                     */
> vprintk_emit
>   spin_lock logbuf_lock
>   log_store
>   spin_unlock logbuf_lock
>   !console_trylock_for_printk
>  return
>                                    /*
>                                     * go to the beginning of the loop,
>                                     * find out there are new messages,
>                                     * lose it
>                                     */
>                                    }
> 
> This patch moves can_use_console() check out of
> console_trylock_for_printk(). Instead it calls it in two
> non-preemptible sections:
> -- console_cont_flush()
>    can_use_console() call happens with spin_lock logbuf_lock
>    taken and local IRQs disabled, local IRQs are not enabled
>    until call_console_drivers() returns.
> 
> -- console_unlock()
>    can_use_console() call happens with spin_lock logbuf_lock
>    taken and local IRQs disabled, local IRQs are not enabled
>    until call_console_drivers() returns.
> 
> In both cases, we need to know that call_console_drivers() call
> was aborted because of !can_use_console() and we must exit
> console_unlock() function.
> 
> This also lets to drop '!cpu_online() && !(con->flags & CON_ANYTIME)'
> test from call_console_drivers().
> 
> At the same time this patch serves as a preparation to enable
> cond_resched for 'in-direct' console_unlock() callers -- the ones
> that come from vprintk_emit(). The 'direct' ones -- the ones that
> do console_lock()/console_unlock() -- already can cond_resched.
> 
> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> ---
>  kernel/printk/printk.c | 71 +++++++++++++++++++++++++-------------------------
>  1 file changed, 36 insertions(+), 35 deletions(-)
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 7ebcfea..5cc0ce6 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -1452,9 +1452,6 @@ static void call_console_drivers(int level,
>  			continue;
>  		if (!con->write)
>  			continue;
> -		if (!cpu_online(smp_processor_id()) &&
> -		    !(con->flags & CON_ANYTIME))
> -			continue;
>  		if (con->flags & CON_EXTENDED)
>  			con->write(con, ext_text, ext_len);
>  		else
> @@ -1500,18 +1497,6 @@ static int have_callable_console(void)
>  }
>  
>  /*
> - * Can we actually use the console at this time on this cpu?
> - *
> - * Console drivers may assume that per-cpu resources have been allocated. So
> - * unless they're explicitly marked as being able to cope (CON_ANYTIME) don't
> - * call them until this CPU is officially up.
> - */
> -static inline int can_use_console(unsigned int cpu)
> -{
> -	return cpu_online(cpu) || have_callable_console();
> -}
> -
> -/*
>   * Try to get console ownership to actually show the kernel
>   * messages from a 'printk'. Return true (and with the
>   * console_lock held, and 'console_locked' set) if it
> @@ -1519,21 +1504,7 @@ static inline int can_use_console(unsigned int cpu)
>   */
>  static int console_trylock_for_printk(void)
>  {
> -	unsigned int cpu = smp_processor_id();
> -
> -	if (!console_trylock())
> -		return 0;
> -	/*
> -	 * If we can't use the console, we need to release the console
> -	 * semaphore by hand to avoid flushing the buffer. We need to hold the
> -	 * console semaphore in order to do this test safely.
> -	 */
> -	if (!can_use_console(cpu)) {
> -		console_locked = 0;
> -		up_console_sem();
> -		return 0;
> -	}
> -	return 1;
> +	return console_trylock();
>  }
>  
>  int printk_delay_msec __read_mostly;
> @@ -2177,10 +2148,23 @@ int is_console_locked(void)
>  	return console_locked;
>  }
>  
> -static void console_cont_flush(char *text, size_t size)
> +/*
> + * Can we actually use the console at this time on this cpu?
> + *
> + * Console drivers may assume that per-cpu resources have been allocated. So
> + * unless they're explicitly marked as being able to cope (CON_ANYTIME) don't
> + * call them until this CPU is officially up.
> + */
> +static inline int can_use_console(void)
> +{
> +	return cpu_online(smp_processor_id()) || have_callable_console();
> +}
> +
> +static bool console_cont_flush(char *text, size_t size)
>  {
>  	unsigned long flags;
>  	size_t len;
> +	bool ret = true;
>  
>  	raw_spin_lock_irqsave(&logbuf_lock, flags);
>  
> @@ -2195,15 +2179,21 @@ static void console_cont_flush(char *text, size_t size)
>  	if (console_seq < log_next_seq && !cont.cons)
>  		goto out;
>  
> +	if (!can_use_console()) {
> +		ret = false;
> +		goto out;
> +	}
> +
>  	len = cont_print_text(text, size);
>  	raw_spin_unlock(&logbuf_lock);
>  	stop_critical_timings();
>  	call_console_drivers(cont.level, NULL, 0, text, len);
>  	start_critical_timings();
>  	local_irq_restore(flags);
> -	return;
> +	return ret;
>  out:
>  	raw_spin_unlock_irqrestore(&logbuf_lock, flags);
> +	return ret;
>  }
>  
>  /**
> @@ -2227,7 +2217,7 @@ void console_unlock(void)
>  	static u64 seen_seq;
>  	unsigned long flags;
>  	bool wake_klogd = false;
> -	bool do_cond_resched, retry;
> +	bool do_cond_resched, retry, aborted = false;
>  
>  	if (console_suspended) {
>  		up_console_sem();
> @@ -2248,7 +2238,12 @@ void console_unlock(void)
>  	console_may_schedule = 0;
>  
>  	/* flush buffered message fragment immediately to console */
> -	console_cont_flush(text, sizeof(text));
> +	if (!console_cont_flush(text, sizeof(text))) {
> +		console_locked = 0;
> +		up_console_sem();
> +		return;
> +	}
> +
>  again:
>  	for (;;) {
>  		struct printk_log *msg;
> @@ -2257,6 +2252,12 @@ again:
>  		int level;
>  
>  		raw_spin_lock_irqsave(&logbuf_lock, flags);
> +
> +		if (!can_use_console()) {
> +			aborted = true;
> +			break;
> +		}
> +
>  		if (seen_seq != log_next_seq) {
>  			wake_klogd = true;
>  			seen_seq = log_next_seq;
> @@ -2337,7 +2338,7 @@ skip:
>  	 * flush, no worries.
>  	 */
>  	raw_spin_lock(&logbuf_lock);
> -	retry = console_seq != log_next_seq;
> +	retry = !aborted && (console_seq != log_next_seq);
>  	raw_spin_unlock_irqrestore(&logbuf_lock, flags);
>  
>  	if (retry && console_trylock())
> -- 
> 2.7.0
> 

Re: [RFC][PATCH -next 2/2] printk: set may_schedule for some of console_trylock callers

[Petr Mladek]

On Sun 2016-01-17 23:23:32, Sergey Senozhatsky wrote:
>  console_unlock() allows to cond_resched() if its caller has
> set `console_may_schedule' to 1 (this functionality present
> since commit 'printk: do cond_resched() between lines while
> outputting to consoles').
> 
> The rules are:
> -- console_lock() always sets `console_may_schedule' to 1
> -- console_trylock() always sets `console_may_schedule' to 0
> 
> However, console_trylock() callers (among them is printk()) are
> not necessarily executing in atomic contexts, and some of them
> can cond_resched() in console_unlock(). So console_trylock()
> can set `console_may_schedule' to 0 only if cond_resched() is
> invalid in the current context, and set it to 1 otherwise.
> 
> The patch also drops explicit preempt_disable()/preempt_enable()
> calls in vprintk_emit().

I do not see any explanation why it is safe to remove these
calls in this patch. If they were required only because of the
can_use_console() call, it would make sense to move this change
to the previous patch. The previous patch moved the
can_use_console() to locations protected by lockbuf_lock that
have disabled preemption because of the lock.


> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> ---
> V2: rcu_preempt_depth() on preempt RCU kernels
> 
>  kernel/printk/printk.c | 13 ++++---------
>  1 file changed, 4 insertions(+), 9 deletions(-)
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index ae641d7..9ac05e0 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -1777,20 +1777,12 @@ asmlinkage int vprintk_emit(int facility, int level,
>  	if (!in_sched) {
>  		lockdep_off();
>  		/*
> -		 * Disable preemption to avoid being preempted while holding
> -		 * console_sem which would prevent anyone from printing to
> -		 * console
> -		 */
> -		preempt_disable();
> -
> -		/*
>  		 * Try to acquire and then immediately release the console
>  		 * semaphore.  The release will print out buffers and wake up
>  		 * /dev/kmsg and syslog() users.
>  		 */
>  		if (console_trylock_for_printk())
>  			console_unlock();
> -		preempt_enable();
>  		lockdep_on();
>  	}
>  
> @@ -2123,7 +2115,10 @@ int console_trylock(void)
>  		return 0;
>  	}
>  	console_locked = 1;
> -	console_may_schedule = 0;
> +	console_may_schedule = !(oops_in_progress ||
> +			irqs_disabled() ||
> +			in_atomic() ||
> +			rcu_preempt_depth());

Is it safe to call cond_resched() when the CPU is not online
and preemption is enabled, please? Your previous patch
suggests that this situation might happen. I guess that
it might break the CPU initialization code.

Best Regards,
Petr


>  	return 1;
>  }
>  EXPORT_SYMBOL(console_trylock);
> -- 
> 2.7.0
> 

Re: [RFC][PATCH -next 1/2] printk: move can_use_console out of console_trylock_for_printk

[Sergey Senozhatsky]

Hello,
thanks for review.

On (01/18/16 16:42), Petr Mladek wrote:
> On Thu 2016-01-14 13:57:22, Sergey Senozhatsky wrote:
> > vprintk_emit() disables preemption around console_trylock_for_printk()
> > and console_unlock() calls for a strong reason -- can_use_console()
> > check. The thing is that vprintl_emit() can be called on a CPU that
> > is not fully brought up yet (!cpu_online()), which potentially can
> > cause problems if console driver accesses per-cpu data. A console
> > driver can explicitly state that it's safe to call it from !online
> > cpu by setting CON_ANYTIME bit in console ->flags. That's why for
> > !cpu_online() can_use_console() iterates all the console to find out
> > if there is a CON_ANYTIME console, otherwise console_unlock() must be
> > avoided.
> > 
> > call_console_drivers(), called from console_cont_flush() and
> > console_unlock(), does the same test during for_each_console() loop.
> > However, we can have the following corner case. Assume that we have 2
> > cpus -- CPU0 is online, CPU1 is !online; and no CON_ANYTIME consoles
> > available.
> > 
> > CPU0 online                        CPU1 !online
> >                                  console_trylock()
> >                                  ...
> >                                  console_unlock()
> 
> Please, where this console_unlock() comes from?

from UP* or DOWN* (_PREPARE f.e.) notifiers on this CPU, for example, we don't
know what's going on there. what prevents it from calling console_trylock(),
grabbing the console_sem and eventually doing console_unlock()? there is
a can_use_console() check, but it handles only one case -- printk().
there is also an extra '!cpu_online() && !CON_ANYTIME' test done for_each_console
in call_console_drivers(), but it's too late -- we already msg_print_text()
and advanced console_seq/console_idx/etc., the message will be lost, we
don't put it back.

> If I get this correctly, this CPU is not online and no CON_ANYTIME
> console exists
> => can_use_console() fails
>   => console_trylock() fails
>     => console_unlock() is not called from vprintk_emit().

the current flow is
vprintk_emit()
  console_trylock_for_printk
    can_use_console fails -- !cpu online and no CON_ANYTIME
      console_unlock() is not called from vprintk_emit()

the missing path
console_trylock
  console_unlock
    for (;;) {
      msg_print_text
      call_console_drivers
        !cpu_online && !CON_ANYTIME -- lost it and repeat again
    }


the new one is

vprintk_emit()
  console_trylock_for_printk  -- ok
    console_unlock
      can_use_console fails -- !cpu online and no CON_ANYTIME

and it also covers the case
console_trylock  -- detour can_use_console()
  console_unlock
    can_use_console fails -- !cpu online and no CON_ANYTIME, abort

	-ss

Re: [RFC][PATCH -next 2/2] printk: set may_schedule for some of console_trylock callers

[Sergey Senozhatsky]

Thanks for the review.

On (01/18/16 17:17), Petr Mladek wrote:
> On Sun 2016-01-17 23:23:32, Sergey Senozhatsky wrote:
> >  console_unlock() allows to cond_resched() if its caller has
> > set `console_may_schedule' to 1 (this functionality present
> > since commit 'printk: do cond_resched() between lines while
> > outputting to consoles').
> > 
> > The rules are:
> > -- console_lock() always sets `console_may_schedule' to 1
> > -- console_trylock() always sets `console_may_schedule' to 0
> > 
> > However, console_trylock() callers (among them is printk()) are
> > not necessarily executing in atomic contexts, and some of them
> > can cond_resched() in console_unlock(). So console_trylock()
> > can set `console_may_schedule' to 0 only if cond_resched() is
> > invalid in the current context, and set it to 1 otherwise.
> > 
> > The patch also drops explicit preempt_disable()/preempt_enable()
> > calls in vprintk_emit().
> 
> I do not see any explanation why it is safe to remove these
> calls in this patch. If they were required only because of the
> can_use_console() call

The comment in the code states

	/*
	 * Disable preemption to avoid being preempted while holding
	 * console_sem which would prevent anyone from printing to
	 * console
	 */

which is not really a problem -- we schedule from console_unlock() with
the console_sem being held, it's fine.

https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/commit/kernel/printk/printk.c?id=8d91f8b15361dfb438ab6eb3b319e2ded43458ff

> it would make sense to move this change to the previous patch.
> The previous patch moved the can_use_console() to locations
> protected by lockbuf_lock that have disabled preemption because
> of the lock.

old:
vprintk_emit
  preempt_disable
   can_use_console
    console_unlock
      spin_lock, save IRQ
      spin_unlock
      call_console_drivers
      restore IRQ
  preempt_enable

new:
vprintk_emit
  console_unlock
    spin_lock, save IRQ
    can_use_console
    spin_unlock
    call_console_drivers
    restore IRQ

so preemption is disabled during the transition from can_use_console()
to call_console_drivers().


[..]
> >  	console_locked = 1;
> > -	console_may_schedule = 0;
> > +	console_may_schedule = !(oops_in_progress ||
> > +			irqs_disabled() ||
> > +			in_atomic() ||
> > +			rcu_preempt_depth());
> 
> Is it safe to call cond_resched() when the CPU is not online
> and preemption is enabled, please? Your previous patch
> suggests that this situation might happen. I guess that
> it might break the CPU initialization code.

CPU notifies are preemptible. CPU_UP_PREPARE/etc. can schedule,
there are GFP_KERNEL kmalloc-s from CPU_UP_PREPARE (where cpu
is not yet online), mutex_lock() calls in cpu_notify handlers,
and so on.

	-ss

Re: [RFC][PATCH -next 1/2] printk: move can_use_console out of console_trylock_for_printk

[Petr Mladek]

On Tue 2016-01-19 09:42:36, Sergey Senozhatsky wrote:
> Hello,
> thanks for review.
> 
> On (01/18/16 16:42), Petr Mladek wrote:
> > On Thu 2016-01-14 13:57:22, Sergey Senozhatsky wrote:
> > > vprintk_emit() disables preemption around console_trylock_for_printk()
> > > and console_unlock() calls for a strong reason -- can_use_console()
> > > check. The thing is that vprintl_emit() can be called on a CPU that
> > > is not fully brought up yet (!cpu_online()), which potentially can
> > > cause problems if console driver accesses per-cpu data. A console
> > > driver can explicitly state that it's safe to call it from !online
> > > cpu by setting CON_ANYTIME bit in console ->flags. That's why for
> > > !cpu_online() can_use_console() iterates all the console to find out
> > > if there is a CON_ANYTIME console, otherwise console_unlock() must be
> > > avoided.
> > > 
> > > call_console_drivers(), called from console_cont_flush() and
> > > console_unlock(), does the same test during for_each_console() loop.
> > > However, we can have the following corner case. Assume that we have 2
> > > cpus -- CPU0 is online, CPU1 is !online; and no CON_ANYTIME consoles
> > > available.
> > > 
> > > CPU0 online                        CPU1 !online
> > >                                  console_trylock()
> > >                                  ...
> > >                                  console_unlock()
> > 
> > Please, where this console_unlock() comes from?
> 
> from UP* or DOWN* (_PREPARE f.e.) notifiers on this CPU, for example, we don't
> know what's going on there. what prevents it from calling console_trylock(),
> grabbing the console_sem and eventually doing console_unlock()? there is
> a can_use_console() check, but it handles only one case -- printk().

So, is it a theoretical problem or do you know about any
particular path where this happens?

Well, it might make sense to get rid of console_trylock_for_printk()
and do the can_use_console() check at the beginning of
unlock_console(). I mean to do

-	if (console_trylock_for_printk())
+	if (console_trylock())
		unlock_console();

But do we really need to repeat the check in every cycle?
can_use_console() checks available consoles and if the CPU
is online. Consoles could not get added or removed when
we own console_sem. It seems that CPUs get disabled
in a process context. Therefore it seems that it might happen
only when unlock_console() gets rescheduled. I guess that
it could not get scheduled back on an offline CPU. So, it
seems that it is enough to check can_use_console() only once at
the beginning.

Or did I miss anything?

Best Regards,
Petr

Re: [RFC][PATCH -next 1/2] printk: move can_use_console out of console_trylock_for_printk

[Sergey Senozhatsky]

Hello,

On (01/19/16 14:31), Petr Mladek wrote:
> > On (01/18/16 16:42), Petr Mladek wrote:
> > > On Thu 2016-01-14 13:57:22, Sergey Senozhatsky wrote:
> > > > vprintk_emit() disables preemption around console_trylock_for_printk()
> > > > and console_unlock() calls for a strong reason -- can_use_console()
> > > > check. The thing is that vprintl_emit() can be called on a CPU that
> > > > is not fully brought up yet (!cpu_online()), which potentially can
> > > > cause problems if console driver accesses per-cpu data. A console
> > > > driver can explicitly state that it's safe to call it from !online
> > > > cpu by setting CON_ANYTIME bit in console ->flags. That's why for
> > > > !cpu_online() can_use_console() iterates all the console to find out
> > > > if there is a CON_ANYTIME console, otherwise console_unlock() must be
> > > > avoided.
> > > > 
> > > > call_console_drivers(), called from console_cont_flush() and
> > > > console_unlock(), does the same test during for_each_console() loop.
> > > > However, we can have the following corner case. Assume that we have 2
> > > > cpus -- CPU0 is online, CPU1 is !online; and no CON_ANYTIME consoles
> > > > available.
> > > > 
> > > > CPU0 online                        CPU1 !online
> > > >                                  console_trylock()
> > > >                                  ...
> > > >                                  console_unlock()
> > > 
> > > Please, where this console_unlock() comes from?
> > 
> > from UP* or DOWN* (_PREPARE f.e.) notifiers on this CPU, for example, we don't
> > know what's going on there. what prevents it from calling console_trylock(),
> > grabbing the console_sem and eventually doing console_unlock()? there is
> > a can_use_console() check, but it handles only one case -- printk().
> 
> So, is it a theoretical problem or do you know about any
> particular path where this happens?

a theoretical one at this point.

> Well, it might make sense to get rid of console_trylock_for_printk()
> and do the can_use_console() check at the beginning of
> unlock_console(). I mean to do
> 
> -	if (console_trylock_for_printk())
> +	if (console_trylock())
> 		unlock_console();

agree, I almost removed it, but decided to keep for a while,
just in case if we would want to add any additional code there.


> But do we really need to repeat the check in every cycle?

well, on every iteration in the best case we check cpu_online()
only. which is what we would have done anyway in vprintk_emit(),
so no additional checks added. at the same time call_console_drivers
does not do '!cpu_online && !CON_ANYTIME' for each console now, so
in some sense there are less checks now (this is far even from a
micro-optimization, just noted).

> can_use_console() checks available consoles and if the CPU
> is online. Consoles could not get added or removed when
> we own console_sem. It seems that CPUs get disabled
> in a process context. Therefore it seems that it might happen
> only when unlock_console() gets rescheduled. I guess that
> it could not get scheduled back on an offline CPU. So, it
> seems that it is enough to check can_use_console() only once at
> the beginning.
> 
> Or did I miss anything?

It does sound interesting, thanks. I was trying to keep the existing
behaviour.

It almost works, there is one case.

console_unlock()    /* w/o can_use_console() in logbuf_lock section */
....
again:
	for (;;) {
		raw_spin_lock_irqsave logbuf_lock
		msg_print_text
		raw_spin_unlock logbuf_lock
		call_console_drivers
		local_irq_restore
	}

	up_console_sem

	raw_spin_lock logbuf_lock
	retry = console_seq != log_next_seq
	raw_spin_unlock_irqrestore logbuf_lock
	
	if retry && console_trylock()
		goto again;


when we up_console_sem(), consoles may appear and disappear, since we
don't keep the semaphore. Suppose that we have OFFLINE cpu and we had a
CON_ANYTIME console, but in between up_console_sem--console_trylock
that single CON_ANYTIME console was removed. So now we have !cpu_online
and !CON_ANYTIME.

So this is why I re-do the can_use_console() check. I can add a bool flag
and do the can_use_console() only once -- when the flag is false, set it
to true on successful can_use_console() and avoid can_use_console() during
this loop; and set the flag to false right after the 'again:' label, which
will imply that console semaphore has been re-acquired and we need to
can_use_console() again.

something like this, perhaps (to be folded.. or should it be a separate
commit -- optimization). will give a test tomorrow.

I reused `bool retry' flag (which is probably a bit hacky, it'll be
better to have a separate byte for this thing). And I moved
can_use_console() from console_cont_flush() to the top -- so if we
are executing the `for (;;)' loop, then can_use_console() was
successful in console_cont_flush() and we have to re-do
can_use_console() only if we released console_sem and jumped to
`again' label.

---
 kernel/printk/printk.c | 29 ++++++++++++++++++++---------
 1 file changed, 20 insertions(+), 9 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 28b2dec..c7a5ce8 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2170,6 +2170,11 @@ static bool console_cont_flush(char *text, size_t size)
 
 	raw_spin_lock_irqsave(&logbuf_lock, flags);
 
+	if (!can_use_console()) {
+		ret = false;
+		goto out;
+	}
+
 	if (!cont.len)
 		goto out;
 
@@ -2181,11 +2186,6 @@ static bool console_cont_flush(char *text, size_t size)
 	if (console_seq < log_next_seq && !cont.cons)
 		goto out;
 
-	if (!can_use_console()) {
-		ret = false;
-		goto out;
-	}
-
 	len = cont_print_text(text, size);
 	raw_spin_unlock(&logbuf_lock);
 	stop_critical_timings();
@@ -2219,7 +2219,7 @@ void console_unlock(void)
 	static u64 seen_seq;
 	unsigned long flags;
 	bool wake_klogd = false;
-	bool do_cond_resched, retry, aborted = false;
+	bool do_cond_resched, retry = false, aborted = false;
 
 	if (console_suspended) {
 		up_console_sem();
@@ -2255,9 +2255,20 @@ again:
 
 		raw_spin_lock_irqsave(&logbuf_lock, flags);
 
-		if (!can_use_console()) {
-			aborted = true;
-			break;
+		/*
+		 * @retry == true implies that we have released console_sem
+		 * and, thus, someone could have added/removed console(-s).
+		 * we need to can_use_console() again. @retry intially set
+		 * to false, because console_cont_flush() does the
+		 * can_use_console() check and we can't execute this loop
+		 * in can_use_console() returned `false` there.
+		 */
+		if (retry) {
+			retry = false;
+			if (!can_use_console()) {
+				aborted = true;
+				break;
+			}
 		}
 
 		if (seen_seq != log_next_seq) {
-- 
2.7.0

Re: [RFC][PATCH -next 2/2] printk: set may_schedule for some of console_trylock callers

[Petr Mladek]

On Tue 2016-01-19 10:15:10, Sergey Senozhatsky wrote:
> Thanks for the review.
> 
> On (01/18/16 17:17), Petr Mladek wrote:
> > On Sun 2016-01-17 23:23:32, Sergey Senozhatsky wrote:
> > >  console_unlock() allows to cond_resched() if its caller has
> > > set `console_may_schedule' to 1 (this functionality present
> > > since commit 'printk: do cond_resched() between lines while
> > > outputting to consoles').
> > > 
> > > The rules are:
> > > -- console_lock() always sets `console_may_schedule' to 1
> > > -- console_trylock() always sets `console_may_schedule' to 0
> > > 
> > > However, console_trylock() callers (among them is printk()) are
> > > not necessarily executing in atomic contexts, and some of them
> > > can cond_resched() in console_unlock(). So console_trylock()
> > > can set `console_may_schedule' to 0 only if cond_resched() is
> > > invalid in the current context, and set it to 1 otherwise.
> > > 
> > > The patch also drops explicit preempt_disable()/preempt_enable()
> > > calls in vprintk_emit().
> > 
> > I do not see any explanation why it is safe to remove these
> > calls in this patch. If they were required only because of the
> > can_use_console() call
> 
> The comment in the code states
> 
> 	/*
> 	 * Disable preemption to avoid being preempted while holding
> 	 * console_sem which would prevent anyone from printing to
> 	 * console
> 	 */

Thanks for the pointer. I missed this in the patch and it was not
obvious from the commit message.

> which is not really a problem -- we schedule from console_unlock() with
> the console_sem being held, it's fine.
> 
> https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/commit/kernel/printk/printk.c?id=8d91f8b15361dfb438ab6eb3b319e2ded43458ff

Yup, I agree that this commit is contradicting the above comment.
The question is if the comment describes the only reason for
disabled preemption.

> [..]
> > >  	console_locked = 1;
> > > -	console_may_schedule = 0;
> > > +	console_may_schedule = !(oops_in_progress ||
> > > +			irqs_disabled() ||

IMHO, we should also check if we are in irq context or not.

> > > +			in_atomic() ||

Hmm, it seems that in_atomic() is not safe enough. There is the
following comment:

/*
 * Are we running in atomic context?  WARNING: this macro cannot
 * always detect atomic context; in particular, it cannot know about
 * held spinlocks in non-preemptible kernels.  Thus it should not be
 * used in the general case to determine whether sleeping is possible.
 * Do not use in_atomic() in driver code.
 */
#define in_atomic()	(preempt_count() != 0)

It might mean that there is no safe way to detect a safe context
on non-preemptible kernels. This might be the most important reason
why we disable preemption when calling console in vprint_emit().


> > > +			rcu_preempt_depth());
> > 
> > Is it safe to call cond_resched() when the CPU is not online
> > and preemption is enabled, please? Your previous patch
> > suggests that this situation might happen. I guess that
> > it might break the CPU initialization code.
> 
> CPU notifies are preemptible. CPU_UP_PREPARE/etc. can schedule,
> there are GFP_KERNEL kmalloc-s from CPU_UP_PREPARE (where cpu
> is not yet online), mutex_lock() calls in cpu_notify handlers,
> and so on.

Hmm, the notifiers are called via __raw_notifier_call_chain().
There is a comment above this function:

 *	Calls each function in a notifier chain in turn.  The functions
 *	run in an undefined context.
 *	All locking must be provided by the caller.

But hmm, you are right that the notifiers do malloc, take mutextes,
etc. The question is if schedule does something in this case. I would
expect that the is no running task assigned to this CPU at this stage.
So, cond_resched is probably a noop in this case.

I am always surprised that printk-world is so tricky.

Best Regards,
Petr

Re: [RFC][PATCH -next 1/2] printk: move can_use_console out of console_trylock_for_printk

[Petr Mladek]

On Wed 2016-01-20 00:00:40, Sergey Senozhatsky wrote:
> > But do we really need to repeat the check in every cycle?
> 
> well, on every iteration in the best case we check cpu_online()
> only. which is what we would have done anyway in vprintk_emit(),
> so no additional checks added. at the same time call_console_drivers
> does not do '!cpu_online && !CON_ANYTIME' for each console now, so
> in some sense there are less checks now (this is far even from a
> micro-optimization, just noted).

Hmm, we need to keep the check in call_console_drivers(). It iterates
over all registered consoles. Only some of them could habe CON_ANYTIME
flag. We need to skip the others when the CPU is not online.


> console_unlock()    /* w/o can_use_console() in logbuf_lock section */
> ....
> again:
> 	for (;;) {
> 		raw_spin_lock_irqsave logbuf_lock
> 		msg_print_text
> 		raw_spin_unlock logbuf_lock
> 		call_console_drivers
> 		local_irq_restore
> 	}
> 
> 	up_console_sem
> 
> 	raw_spin_lock logbuf_lock
> 	retry = console_seq != log_next_seq
> 	raw_spin_unlock_irqrestore logbuf_lock
> 	
> 	if retry && console_trylock()
> 		goto again;
> 
> 
> when we up_console_sem(), consoles may appear and disappear, since we
> don't keep the semaphore. Suppose that we have OFFLINE cpu and we had a
> CON_ANYTIME console, but in between up_console_sem--console_trylock
> that single CON_ANYTIME console was removed. So now we have !cpu_online
> and !CON_ANYTIME.

Ah, I have missed that the console_sem is released/taken before goto
again. Hmm, your proposed solution adds even more twists into the code.
I think how to make it easier. I think that we could move the again:
target and call console_cont_flush() when there is some new content.
It is a corner case, anyway. Then we could do:


	do_cond_resched = console_may_schedule;
	console_may_schedule = 0;

+again:
+	if (!can_use_console()) {
+		console_locked = 0;
+		up_console_sem();
+		return;
	}

	/* flush buffered message fragment immediately to console */
	console_cont_flush(text, sizeof(text));
-again:
	for (;;) {
		struct printk_log *msg;


Then we remove this check from console_trylock_for_printk() and
eventually remove this function altogether.

It means that the code will be easier and protected against the
theoretical race.

How does that sound, please?

Best Regards,
Petr

Re: [RFC][PATCH -next 2/2] printk: set may_schedule for some of console_trylock callers

[Sergey Senozhatsky]

Hello,

On (01/19/16 16:18), Petr Mladek wrote:
[..]
> > > >  	console_locked = 1;
> > > > -	console_may_schedule = 0;
> > > > +	console_may_schedule = !(oops_in_progress ||
> > > > +			irqs_disabled() ||
> 
> IMHO, we should also check if we are in irq context or not.
> 
> > > > +			in_atomic() ||
> 
> Hmm, it seems that in_atomic() is not safe enough. There is the
> following comment:
>
> /*
>  * Are we running in atomic context?  WARNING: this macro cannot
>  * always detect atomic context; in particular, it cannot know about
>  * held spinlocks in non-preemptible kernels.  Thus it should not be
>  * used in the general case to determine whether sleeping is possible.
>  * Do not use in_atomic() in driver code.
>  */
> #define in_atomic()	(preempt_count() != 0)
> 

I had in_interrupt() check in trylock, but dropped it. As of 4.4 in_interrupt()
does the following

#define hardirq_count()	(preempt_count() & HARDIRQ_MASK)
#define softirq_count()	(preempt_count() & SOFTIRQ_MASK)
#define irq_count()	(preempt_count() & (HARDIRQ_MASK | SOFTIRQ_MASK \
				 | NMI_MASK))

#define in_interrupt()		(irq_count())

while in_atomic() does

#define in_atomic()	(preempt_count() != 0)

so in_atomic() covers both preemption disabled and in_interrupt().


I take your `non-preemptible kernel' point, thanks.


> It might mean that there is no safe way to detect a safe context
> on non-preemptible kernels. This might be the most important reason
> why we disable preemption when calling console in vprint_emit().

well, if we run a !PREEMPT_COUNT kernel, then
#define preempt_disable()	barrier()
#define preempt_enable()	barrier()
#define preemptible()		0

so I don't think that preempt_disable()/preempt_enable() were for
non-preempt kernels there.

otoh, preempt_count still counts irqs, because in_interrupt() (and friends)
macro is supposed to work regardless the preempt config selection, so we
just lose preempt_disable bit from preempt_count... hm... I think I'll
just introduce preemptible() check there.

for preempt kernels, preemptible() does
#define preemptible()	(preempt_count() == 0 && !irqs_disabled())

and for !preempt kernels
#define preemptible()	0

iow, no cond_resched() in console_unlock() called from vprintk_emit()
on non-preempt kernels.

so the console_may_schedule now turns into (composed in mail-app, not
actually tested):


console_may_schedule = !oops_in_progress && preemptible() &&
			!rcu_preempt_depth();

	/*
	 * or a slightly less readable version
	 * !(oops_in_progress || !preemptible() || rcu_preempt_depth())
	 */


preemptible() implies "preempt_enabled && !in_interrupt() && !irqs_disabled()";
or is always 0 (so it can be optimized out).


will test it, but looks legit to me.


> > > > +			rcu_preempt_depth());
> > > 
> > > Is it safe to call cond_resched() when the CPU is not online
> > > and preemption is enabled, please? Your previous patch
> > > suggests that this situation might happen. I guess that
> > > it might break the CPU initialization code.
> > 
> > CPU notifies are preemptible. CPU_UP_PREPARE/etc. can schedule,
> > there are GFP_KERNEL kmalloc-s from CPU_UP_PREPARE (where cpu
> > is not yet online), mutex_lock() calls in cpu_notify handlers,
> > and so on.
> 
> Hmm, the notifiers are called via __raw_notifier_call_chain().
> There is a comment above this function:
> 
>  *	Calls each function in a notifier chain in turn.  The functions
>  *	run in an undefined context.
>  *	All locking must be provided by the caller.
> 
> But hmm, you are right that the notifiers do malloc, take mutextes,
> etc. The question is if schedule does something in this case. I would
> expect that the is no running task assigned to this CPU at this stage.
> So, cond_resched is probably a noop in this case.

CPU's run queue is not marked online yet at this point (it becomes online
in response to CPU_ONLINE notification). so there is not too many tasks to
schedule on that CPU -- swapper/X perhaps.. migration/X?.

> I am always surprised that printk-world is so tricky.

	-ss

Re: [RFC][PATCH -next 1/2] printk: move can_use_console out of console_trylock_for_printk

[Sergey Senozhatsky]

On (01/19/16 17:16), Petr Mladek wrote:
> On Wed 2016-01-20 00:00:40, Sergey Senozhatsky wrote:
> > > But do we really need to repeat the check in every cycle?
> > 
> > well, on every iteration in the best case we check cpu_online()
> > only. which is what we would have done anyway in vprintk_emit(),
> > so no additional checks added. at the same time call_console_drivers
> > does not do '!cpu_online && !CON_ANYTIME' for each console now, so
> > in some sense there are less checks now (this is far even from a
> > micro-optimization, just noted).
> 
> Hmm, we need to keep the check in call_console_drivers(). It iterates
> over all registered consoles. Only some of them could habe CON_ANYTIME
> flag. We need to skip the others when the CPU is not online.

oh... good point, you are right! my bad. so we basically need both. the
first one (can_use_console() before call_console_drivers()) ensures that
it's _generally_ OK to call call_console_drivers() later and that it will
not drain messages, the second one _in_ call_console_drivers() filters out
only CON_ANYTIME consoles if !cpu_online(), but by this time we are sure
that there is at least one CON_ANYTIME console.

[..]
> > when we up_console_sem(), consoles may appear and disappear, since we
> > don't keep the semaphore. Suppose that we have OFFLINE cpu and we had a
> > CON_ANYTIME console, but in between up_console_sem--console_trylock
> > that single CON_ANYTIME console was removed. So now we have !cpu_online
> > and !CON_ANYTIME.
> 
> Ah, I have missed that the console_sem is released/taken before goto
> again. Hmm, your proposed solution adds even more twists into the code.
> I think how to make it easier. I think that we could move the again:
> target and call console_cont_flush() when there is some new content.
> It is a corner case, anyway. Then we could do:
> 
> 
> 	do_cond_resched = console_may_schedule;
> 	console_may_schedule = 0;
> 
> +again:
> +	if (!can_use_console()) {
> +		console_locked = 0;
> +		up_console_sem();
> +		return;
> 	}
> 
> 	/* flush buffered message fragment immediately to console */
> 	console_cont_flush(text, sizeof(text));
> -again:
> 	for (;;) {
> 		struct printk_log *msg;
> 

looks better. we do extra IRQ disable/enable (spin lock irq) when we jump
to `again' label, but I don't think this introduces any significant overhead.
however, if it does, we always can avoid extra console_cont_flush() by simply
checking @retry -- it's `false' only once, when we execute this part for
the first time in the current console_unlock() call; all goto-jumps imply
that @retry is `true'.

IOW:

	bool retry = false;

again:
	can_use_console

	if (!retry)	/* if we jumped to again, retry is true */
		console_cont_flush
	
	for (;;) {
		...
	}

	retry = ...

	if retry && console_trylock()
		goto retry;


> Then we remove this check from console_trylock_for_printk() and
> eventually remove this function altogether.

yes, that was the plan :)

> It means that the code will be easier and protected against the
> theoretical race.
> 
> How does that sound, please?

sounds good, thanks.

> Best Regards,
> Petr

	-ss

Re: [RFC][PATCH -next 1/2] printk: move can_use_console out of console_trylock_for_printk

[Petr Mladek]

On Wed 2016-01-20 13:18:04, Sergey Senozhatsky wrote:
> On (01/19/16 17:16), Petr Mladek wrote:
> > 	do_cond_resched = console_may_schedule;
> > 	console_may_schedule = 0;
> > 
> > +again:
> > +	if (!can_use_console()) {
> > +		console_locked = 0;
> > +		up_console_sem();
> > +		return;
> > 	}
> > 
> > 	/* flush buffered message fragment immediately to console */
> > 	console_cont_flush(text, sizeof(text));
> > -again:
> > 	for (;;) {
> > 		struct printk_log *msg;
> > 
> 
> looks better. we do extra IRQ disable/enable (spin lock irq) when we jump
> to `again' label, but I don't think this introduces any significant overhead.
> however, if it does, we always can avoid extra console_cont_flush() by simply
> checking @retry -- it's `false' only once, when we execute this part for
> the first time in the current console_unlock() call; all goto-jumps imply
> that @retry is `true'.

IMHO, the extra spin_lock/unlock does not harm much. We do this
for each line in the for(;;) cycle anyway. But the check for retry
value is clever. We could use this if others would want to preserve
the existing behavior and call console_cont_flush() only once.

Best Regards,
Petr

Re: [RFC][PATCH -next 2/2] printk: set may_schedule for some of console_trylock callers

[Sergey Senozhatsky]

On (01/20/16 12:50), Sergey Senozhatsky wrote:
[..]
> > Hmm, the notifiers are called via __raw_notifier_call_chain().
> > There is a comment above this function:
> > 
> >  *	Calls each function in a notifier chain in turn.  The functions
> >  *	run in an undefined context.
> >  *	All locking must be provided by the caller.
> > 
> > But hmm, you are right that the notifiers do malloc, take mutextes,
> > etc. The question is if schedule does something in this case. I would
> > expect that the is no running task assigned to this CPU at this stage.
> > So, cond_resched is probably a noop in this case.

I did some modifications to notifier, just to check how real that theoretical
race condition can possible be.

And here are notifications sent by *offline* cpu to itself (to offline cpu).

[   73.861462] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:sched_cpu_active+0x0/0x55
[   73.861466] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:sched_domains_numa_masks_update+0x0/0xd
[   73.861469] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:cpuset_cpu_active+0x0/0x42
[   73.861473] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:vgetcpu_cpu_notifier+0x0/0x30
[   73.861476] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:uncore_cpu_notifier+0x0/0x20f
[   73.861480] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:perf_cpu_notify+0x0/0x36
[   73.861483] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:x86_pmu_notifier+0x0/0xb0
[   73.861490] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:cstate_cpu_notifier+0x0/0x1c1
[   73.861493] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:migration_call+0x0/0x328
[   73.861496] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:smpboot_thread_call+0x0/0x28
[   73.861500] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:workqueue_cpu_up_callback+0x0/0x426
[   73.861503] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:page_alloc_cpu_notify+0x0/0x41
[   73.861506] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:slab_cpuup_callback+0x0/0xed
[   73.861508] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:sched_ilb_notifier+0x0/0x78
[   73.861511] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:rcu_cpu_notify+0x0/0x3f0
[   73.861514] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:rb_cpu_notify+0x0/0xde
[   73.861516] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:rb_cpu_notify+0x0/0xde
[   73.861520] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:radix_tree_callback+0x0/0x50
[   73.861522] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:timer_cpu_notify+0x0/0x136
[   73.861525] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:hrtimer_cpu_notify+0x0/0x290
[   73.861528] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:hotplug_cfd+0x0/0x80
[   73.861531] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:buffer_cpu_notify+0x0/0x85
[   73.861533] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:ratelimit_handler+0x0/0x27
[   73.861536] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:cpu_callback+0x0/0x150
[   73.861538] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:relay_hotcpu_callback+0x0/0xc7
[   73.861540] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:hotplug_hrtick+0x0/0x76
[   73.861543] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:memcg_cpu_hotplug_callback+0x0/0x3d
[   73.861546] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:blk_cpu_notify+0x0/0x8d
[   73.861549] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:blk_mq_main_cpu_notify+0x0/0x67
[   73.861552] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:blk_mq_queue_reinit_notify+0x0/0x1b3
[   73.861556] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:dev_cpu_callback+0x0/0x195
[   73.861559] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:cpu_callback+0x0/0x4e
[   73.861562] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:vmstat_cpuup_callback+0x0/0x83
[   73.861565] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:percpu_counter_hotcpu_callback+0x0/0x8b
[   73.861567] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:cpu_hotplug_notify+0x0/0x65
[   73.861571] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:topology_cpu_callback+0x0/0x6e
[   73.861574] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:cacheinfo_cpu_callback+0x0/0x76
[   73.861577] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:mce_cpu_callback+0x0/0xee
[   73.861580] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:mc_cpu_callback+0x0/0xad
[   73.861582] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:console_cpu_notify+0x0/0x35
[   73.861587] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:acpi_cpu_soft_notify+0x0/0xe0 [processor]
[   73.861590] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:boost_notify+0x0/0x5f [acpi_cpufreq]
[   73.861593] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:cpufreq_cpu_callback+0x0/0x46
[   73.861597] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:coretemp_cpu_callback+0x0/0x1bd [coretemp]
[   73.861599] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:workqueue_cpu_down_callback+0x0/0xde
[   73.861602] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:hpet_cpuhp_notify+0x0/0x162
[   73.861604] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:sched_cpu_inactive+0x0/0x27
[   73.861606] SELF NOTIFY [by swapper/2] from cpu:2 to:2 (dec:2) action name:CPU_STARTING [code:10] callback:cpuset_cpu_inactive+0x0/0x231


so on my quite small x86_64 kernel (I'm trying to keep unneeded stuff out of the image), that's a bit
bigger than I'd expected.




so I have the new patch set. and it seems to be working on my simple tests.

but... hm... a bit concerned about CPU_DOWN path.

DOWN notification sequence is
CPU_DOWN_PREPARE -> __cpu_disable() -> CPU_DYING -> CPU_DEAD -> CPU_POST_DEAD

__cpu_disable() is getting called before cpu_notify(CPU_DYING), and
__cpu_disable() sets set_cpu_online(cpu, false).

kernel/sched/core.c   migration_call()

	case CPU_DYING:
		sched_ttwu_pending();
		/* Update our root-domain */
		raw_spin_lock_irqsave(&rq->lock, flags);
		if (rq->rd) {
			BUG_ON(!cpumask_test_cpu(cpu, rq->rd->span));
			set_rq_offline(rq);
		}
		migrate_tasks(rq);
		BUG_ON(rq->nr_running != 1); /* the migration thread */
		raw_spin_unlock_irqrestore(&rq->lock, flags);
		break;

so it's only when CPU is already !cpu_online scheduler does set_rq_offline() and
migrate_tasks(rq).

the good news is that CPU_DOWN_PREPARE disables CPU's rq ->hrtick_timer,
so no rq ticks. but what happens on !CONFIG_SCHED_HRTICK systems?... scheduler_tick
is getting disabled because we clear APIC and thus stop timer interrupts? I have a
little knowledge here, sorry. so I'll better ask. Is it possible to get !online cpu
and still iterating in this console_unlock() loop? I suspect that the answer is no,
but better be sure.

	-ss

Re: [RFC][PATCH -next 2/2] printk: set may_schedule for some of console_trylock callers

[Petr Mladek]

On Wed 2016-01-20 12:50:56, Sergey Senozhatsky wrote:
> so in_atomic() covers both preemption disabled and in_interrupt().

I see.

> well, if we run a !PREEMPT_COUNT kernel, then
> #define preempt_disable()	barrier()
> #define preempt_enable()	barrier()
> #define preemptible()		0
> 
> so I don't think that preempt_disable()/preempt_enable() were for
> non-preempt kernels there.
> 
> otoh, preempt_count still counts irqs, because in_interrupt() (and friends)
> macro is supposed to work regardless the preempt config selection, so we
> just lose preempt_disable bit from preempt_count... hm... I think I'll
> just introduce preemptible() check there.
> 
> for preempt kernels, preemptible() does
> #define preemptible()	(preempt_count() == 0 && !irqs_disabled())
> 
> and for !preempt kernels
> #define preemptible()	0
> 
> iow, no cond_resched() in console_unlock() called from vprintk_emit()
> on non-preempt kernels.
> 
> so the console_may_schedule now turns into (composed in mail-app, not
> actually tested):
> 
> 
> console_may_schedule = !oops_in_progress && preemptible() &&
> 			!rcu_preempt_depth();

I though about it from some other side and I wonder if we need all
the console_may_schedule stuff at all.

printk_emit() has the following code:

	/* This stops the holder of console_sem just where we want him */
	local_irq_save(flags);
[...]
	lockdep_off();
	raw_spin_lock(&logbuf_lock);
	logbuf_cpu = this_cpu;

[...]

	logbuf_cpu = UINT_MAX;
	raw_spin_unlock(&logbuf_lock);
	lockdep_on();
	local_irq_restore(flags);

	/* If called from the scheduler, we can not call up(). */
	if (!in_sched) {
		lockdep_off();
		/*
		 * Disable preemption to avoid being preempted while holding
		 * console_sem which would prevent anyone from printing to
		 * console
		 */
		preempt_disable();

		/*
		 * Try to acquire and then immediately release the console
		 * semaphore.  The release will print out buffers and wake up
		 * /dev/kmsg and syslog() users.
		 */
		if (console_trylock_for_printk())
			console_unlock();
		preempt_enable();


First, the message "This stops the holder of console_sem just where we
want him" is suspitious. It is there sice the initial git commit on
2005-04-16. I do not understand how this could block the console
holder on another CPU. I think that it rather allows to make the
recursion detection without the lockbuf lock. But this is not
that important.

More interesting is the counter part:

	raw_spin_unlock(&logbuf_lock);
	lockdep_on();
	local_irq_restore(flags);

raw_spin_unlock() calls preempt_enable() that calls
preempt_schedule(). It does nothing here because IRQs
are still disabled.

But if we do not need the lockdep_on() hack, we could use
raw_spin_unlock_irqrestore(&lockbuf_lock, flags). It means
that we do not call cond_resched here "only by chance".

In each case, preemtible kernel seems to be free to reschedule
after we enable the inrerrupts. By other words, preemptible kernel
seems to be able to reschedule in printk() already these days.
Why it might work?

I think that it might work because cond_resched() or rather
preempt_schedule() are clever enough. They both check
preempt_count and do nothing if preemtion is disabled.

As a result, I think that we do not need the extra checks
for the save context in printk(). IMHO, it is safe to remove
all the console_may_schedule stuff and also remove the extra
preempt_disable/preempt_enable() in vprintk_emit().

Or did I miss anything?

Best Regards,
Petr

Re: [RFC][PATCH -next 2/2] printk: set may_schedule for some of console_trylock callers

[Petr Mladek]

On Wed 2016-01-20 20:51:43, Sergey Senozhatsky wrote:
> On (01/20/16 12:50), Sergey Senozhatsky wrote:
> [..]
> > > Hmm, the notifiers are called via __raw_notifier_call_chain().
> > > There is a comment above this function:
> > > 
> > >  *	Calls each function in a notifier chain in turn.  The functions
> > >  *	run in an undefined context.
> > >  *	All locking must be provided by the caller.
> > > 
> > > But hmm, you are right that the notifiers do malloc, take mutextes,
> > > etc. The question is if schedule does something in this case. I would
> > > expect that the is no running task assigned to this CPU at this stage.
> > > So, cond_resched is probably a noop in this case.
> 
> I did some modifications to notifier, just to check how real that theoretical
> race condition can possible be.

After all I think that this was a false alarm. As you said, there are
used locks in the notifiers. I do not see any special handling of
preemption. If the locks do not care about this special CPU state
and rescheduling, printk should not need to take care of it as well.

In each case, thanks a lot for the analyze. These are all interesting
things and any piece of information helps better understanding.

Best Regards,
Petr

Re: [RFC][PATCH -next 2/2] printk: set may_schedule for some of console_trylock callers

[Sergey Senozhatsky]

Hello,

On (01/20/16 13:31), Petr Mladek wrote:
[..]
> > console_may_schedule = !oops_in_progress && preemptible() &&
> > 			!rcu_preempt_depth();
> 
> I though about it from some other side and I wonder if we need all
> the console_may_schedule stuff at all.

interesting, thanks.

> printk_emit() has the following code:
> 
> 	/* This stops the holder of console_sem just where we want him */
> 	local_irq_save(flags);
> [...]
> 	lockdep_off();
> 	raw_spin_lock(&logbuf_lock);
> 	logbuf_cpu = this_cpu;
> 
> [...]
> 
> 	logbuf_cpu = UINT_MAX;
> 	raw_spin_unlock(&logbuf_lock);
> 	lockdep_on();
> 	local_irq_restore(flags);
> 
> 	/* If called from the scheduler, we can not call up(). */
> 	if (!in_sched) {
> 		lockdep_off();
> 		/*
> 		 * Disable preemption to avoid being preempted while holding
> 		 * console_sem which would prevent anyone from printing to
> 		 * console
> 		 */
> 		preempt_disable();
> 
> 		/*
> 		 * Try to acquire and then immediately release the console
> 		 * semaphore.  The release will print out buffers and wake up
> 		 * /dev/kmsg and syslog() users.
> 		 */
> 		if (console_trylock_for_printk())
> 			console_unlock();
> 		preempt_enable();
> 
> 
> First, the message "This stops the holder of console_sem just where we
> want him" is suspitious.

this comment is irrelevant, as of today. it was, a long time ago, because
the entire thing was a bit different (linux-2.4.21 kernel/printk.c)

        /* This stops the holder of console_sem just where we want him */
        spin_lock_irqsave(&logbuf_lock, flags);

logbuf_lock does stop the holder, local_irq_save() does not, you are right.


> It is there sice the initial git commit on 2005-04-16. I do not
> understand how this could block the console holder on another CPU.
> I think that it rather allows to make the recursion detection without
> the lockbuf lock. But this is not
> that important.
> 
> More interesting is the counter part:
> 
> 	raw_spin_unlock(&logbuf_lock);
> 	lockdep_on();
> 	local_irq_restore(flags);
> 
> raw_spin_unlock() calls preempt_enable() that calls
> preempt_schedule(). It does nothing here because IRQs
> are still disabled.
> 
> But if we do not need the lockdep_on() hack, we could use
> raw_spin_unlock_irqrestore(&lockbuf_lock, flags). It means
> that we do not call cond_resched here "only by chance".
> 
> In each case, preemtible kernel seems to be free to reschedule
> after we enable the inrerrupts. By other words, preemptible kernel
> seems to be able to reschedule in printk() already these days.
> Why it might work?
> 
> I think that it might work because cond_resched() or rather
> preempt_schedule() are clever enough. They both check
> preempt_count and do nothing if preemtion is disabled.

is cond_resched() clever enough for vprintk_emit()->onsole_unlock()?
I think it can schedule from rcu read critical section, for example.

rcu_read_lock
  printk
    vprintk_emit
      console_unlock
        cond_resched     << will schedule
rcu_read_unlock

because _cond_resched()->should_resched(0) test
	unlikely(preempt_count() == preempt_offset && tif_need_resched());

it does care about preempt_disable (if the kernel is CONFIG_PREEMPT_COUNT,
though) and IRQ count, but no rcu preempt count check. and, I think, we also
don't want to schedule when we are in oops_in_progress.
so we can (probably...) get rid of console_may_schedule, but I don't think
we can unconditionally cond_resched() from console_unlock().

> As a result, I think that we do not need the extra checks
> for the save context in printk(). IMHO, it is safe to remove
> all the console_may_schedule stuff and also remove the extra
> preempt_disable/preempt_enable() in vprintk_emit().
> 
> Or did I miss anything?

hm... I suspect the reason we have console_may_schedule is
console_conditional_schedule() - console_sem owner may want
to have an internal logic to re-schedule [fwiw], while still
holding the console_sem. tty/vt/vt.c or video/console/fbcon.c
for example. (in 2.4 kernel: video/fbcon.c and char/console.c).

cond_resched() helps in console_unlock(); console_conditional_schedule()
is called after console_lock() and _before_ console_unlock()....

static void fbcon_redraw_move(struct vc_data *vc, struct display *p,
			      int line, int count, int dy)
{
	unsigned short *s = (unsigned short *)
		(vc->vc_origin + vc->vc_size_row * line);

	while (count--) {
		unsigned short *start = s;
		unsigned short *le = advance_row(s, 1);
		unsigned short c;
		int x = 0;
		unsigned short attr = 1;

		do {
			c = scr_readw(s);
			if (attr != (c & 0xff00)) {
				attr = c & 0xff00;
				if (s > start) {
					fbcon_putcs(vc, start, s - start,
						    dy, x);
					x += s - start;
					start = s;
				}
			}
			console_conditional_schedule();
			s++;
		} while (s < le);
		if (s > start)
			fbcon_putcs(vc, start, s - start, dy, x);
		console_conditional_schedule();
		dy++;
	}
}

dunno... for non-preempt kernels, perhaps?


	-ss

> Best Regards,
> Petr
> 

Re: [RFC][PATCH -next 2/2] printk: set may_schedule for some of console_trylock callers

[Sergey Senozhatsky]

On (01/21/16 10:25), Sergey Senozhatsky wrote:
[..]
> > First, the message "This stops the holder of console_sem just where we
> > want him" is suspitious.
> 
> this comment is irrelevant, as of today. it was, a long time ago, because
> the entire thing was a bit different (linux-2.4.21 kernel/printk.c)
> 
>         /* This stops the holder of console_sem just where we want him */
>         spin_lock_irqsave(&logbuf_lock, flags);
> 
> logbuf_lock does stop the holder, local_irq_save() does not, you are right.

I meant 'irrelevant on its current place'.

[..]
> > As a result, I think that we do not need the extra checks
> > for the save context in printk(). IMHO, it is safe to remove
> > all the console_may_schedule stuff and also remove the extra
> > preempt_disable/preempt_enable() in vprintk_emit().
> > 
> > Or did I miss anything?
> 
> hm... I suspect the reason we have console_may_schedule is
> console_conditional_schedule() - console_sem owner may want
> to have an internal logic to re-schedule [fwiw], while still
> holding the console_sem. tty/vt/vt.c or video/console/fbcon.c
> for example. (in 2.4 kernel: video/fbcon.c and char/console.c).
> 
> cond_resched() helps in console_unlock(); console_conditional_schedule()
> is called after console_lock() and _before_ console_unlock()....

for CONFIG_PREEMPT_COUNT kernel we can do something like

+void __sched console_conditional_schedule(void)
+{
+       if (!oops_in_progress && preemptible() && !rcu_preempt_depth())
+               cond_resched();
+}

and in console_unlock()

-               if (do_cond_resched)
-                       cond_resched();
+               console_conditional_schedule();



but for !CONFIG_PREEMPT_COUNT we can't. because of currently held spin_locks/etc
that we don't know about.

`console_may_schedule' carries a bit of important information for
console_conditional_schedule() caller. if it has acquired console_sem
via console_lock() - then it can schedule, if via console_trylock() - it cannot.

the last `if via console_trylock() - it cannot' rule is not always true,
we clearly can have printk()->console_unlock() from non-atomic contexts
(if we know that its non-atomic, which is not the case with !PREEMPT_COUNT).

	-ss

Re: [RFC][PATCH -next 2/2] printk: set may_schedule for some of console_trylock callers

[Petr Mladek]

On Thu 2016-01-21 14:51:46, Sergey Senozhatsky wrote:
> On (01/21/16 10:25), Sergey Senozhatsky wrote:
> [..]
> > > First, the message "This stops the holder of console_sem just where we
> > > want him" is suspitious.
> > 
> > this comment is irrelevant, as of today. it was, a long time ago, because
> > the entire thing was a bit different (linux-2.4.21 kernel/printk.c)
> > 
> >         /* This stops the holder of console_sem just where we want him */
> >         spin_lock_irqsave(&logbuf_lock, flags);
> > 
> > logbuf_lock does stop the holder, local_irq_save() does not, you are right.
> 
> I meant 'irrelevant on its current place'.

Thanks a lot for confirmation.

> [..]
> > > As a result, I think that we do not need the extra checks
> > > for the save context in printk(). IMHO, it is safe to remove
> > > all the console_may_schedule stuff and also remove the extra
> > > preempt_disable/preempt_enable() in vprintk_emit().
> > > 
> > > Or did I miss anything?
> > 
> > hm... I suspect the reason we have console_may_schedule is
> > console_conditional_schedule() - console_sem owner may want
> > to have an internal logic to re-schedule [fwiw], while still
> > holding the console_sem. tty/vt/vt.c or video/console/fbcon.c
> > for example. (in 2.4 kernel: video/fbcon.c and char/console.c).
> > 
> > cond_resched() helps in console_unlock(); console_conditional_schedule()
> > is called after console_lock() and _before_ console_unlock()....
> 
> for CONFIG_PREEMPT_COUNT kernel we can do something like
> 
> +void __sched console_conditional_schedule(void)
> +{
> +       if (!oops_in_progress && preemptible() && !rcu_preempt_depth())
> +               cond_resched();
> +}
> 
> and in console_unlock()
> 
> -               if (do_cond_resched)
> -                       cond_resched();
> +               console_conditional_schedule();
>
>
> but for !CONFIG_PREEMPT_COUNT we can't. because of currently held spin_locks/etc
> that we don't know about.

Ah, I was not aware that we did not have information about preemption
without PREEMPT_COUNT.


> `console_may_schedule' carries a bit of important information for
> console_conditional_schedule() caller. if it has acquired console_sem
> via console_lock() - then it can schedule, if via console_trylock() - it cannot.
> 
> the last `if via console_trylock() - it cannot' rule is not always true,
> we clearly can have printk()->console_unlock() from non-atomic contexts
> (if we know that its non-atomic, which is not the case with !PREEMPT_COUNT).

By other words, we could automatically detect save context for
cond_resched() only if PREEMPT_COUNT is enabled. Otherwise, we need to
keep the current logic (heuristic). Do I get it correctly, please?

I would personally wait a bit for Jack's async console printing.
It will call console only if oops_in_progress is set. It means that
this partial optimization won't be needed at all.

The other (first) patch still makes sense in the simplified form.


Best Regards,
Petr

Re: [RFC][PATCH -next 2/2] printk: set may_schedule for some of console_trylock callers

[Sergey Senozhatsky]

Hello,

On (01/22/16 10:48), Petr Mladek wrote:
[..]
> > and in console_unlock()
> > 
> > -               if (do_cond_resched)
> > -                       cond_resched();
> > +               console_conditional_schedule();
> >
> >
> > but for !CONFIG_PREEMPT_COUNT we can't. because of currently held spin_locks/etc
> > that we don't know about.
> 
> Ah, I was not aware that we did not have information about preemption
> without PREEMPT_COUNT.

yes, for example,

static inline void __raw_spin_lock(raw_spinlock_t *lock)
{
	preempt_disable();
	spin_acquire(&lock->dep_map, 0, 0, _RET_IP_);
	LOCK_CONTENDED(lock, do_raw_spin_trylock, do_raw_spin_lock);
}

where preempt_disable()  include/linux/preempt.h

...
#else /* !CONFIG_PREEMPT_COUNT */

/*
 * Even if we don't have any preemption, we need preempt disable/enable
 * to be barriers, so that we don't have things like get_user/put_user
 * that can cause faults and scheduling migrate into our preempt-protected
 * region.
 */
#define preempt_disable()			barrier()
#define preempt_enable()			barrier()


so on !CONFIG_PREEMPT_COUNT kernels we can't rely on console_trylock()
'magic', we need the existing rules.

> > `console_may_schedule' carries a bit of important information for
> > console_conditional_schedule() caller. if it has acquired console_sem
> > via console_lock() - then it can schedule, if via console_trylock() - it cannot.
> > 
> > the last `if via console_trylock() - it cannot' rule is not always true,
> > we clearly can have printk()->console_unlock() from non-atomic contexts
> > (if we know that its non-atomic, which is not the case with !PREEMPT_COUNT).
> 
> By other words, we could automatically detect save context for
> cond_resched() only if PREEMPT_COUNT is enabled. Otherwise, we need to
> keep the current logic (heuristic). Do I get it correctly, please?

yes, I think so.

> I would personally wait a bit for Jack's async console printing.
> It will call console only if oops_in_progress is set. It means that
> this partial optimization won't be needed at all.

ok, thanks. I'd love to see Jan's printk() rework being merged. I have 99 problems
with printk() and console_unlock(). People usually are not aware of the secrets that
printk-console_unlock have; and tend to think that printk is just 'a kernel way' of
spelling printf, with all the consequences that follows -- excessive printk usage,
RCU stalls, soft lockups, etc. And that printk abuse does not necessarily hit the
abuser. A completely 'innocent' user space application that does a syscall which
involves console_lock-console_unlock, can spend seconds in console_unlock pushing
someone's data to console_drivers. console_lock and console_unlock, I think, have a
bit misleading naming. _lock has acquire semantics, _unlock, however, does not
simply release the lock. I even think it'd be good to have console_unlock_fast(),
that would just up_console_sem() w/o any penalty. So some of console_unlock() that
are 'accessible' by user-space /* for example,
  tty_open()
    tty_lookup_driver()
      console_device()
        console_lock()
        console_unlock()

or reading from /proc/consoles, and so on and forth */
could be replaced with console_unlock_fast().

The patch in question is simply a further extension on Tejun's work. And
these two patches already made my life a bit simpler, albeit not all of the
printk/console_unlock problems were addressed.

Jan's patch set is a much more complicated effort, and it may take 2 or
3 (??) kernel releases to finish (there are corner cases: for example,
workers can stall during OOM, etc.), I'd be happy to see it in -next for 4.6,
personally, not sure how realistic this expectation is.

> The other (first) patch still makes sense in the simplified form.

thanks. let's do it this way - I'll keep the preempt disable/enable
removal patch the last in the series, so we can easily drop it (if
Jan's rework is much-much closer). How does that sound?

	-ss

> Best Regards,
> Petr
>