Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1440446 > unrolled thread

Re: [Query] Preemption (hogging) of the work handler

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.

Contents

  Re: [Query] Preemption (hogging) of the work handler Jan Kara <jack@suse.cz> - 2016-07-11 12:30 +0200
    Re: [Query] Preemption (hogging) of the work handler Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2016-07-11 17:50 +0200
      Re: [Query] Preemption (hogging) of the work handler "Rafael J. Wysocki" <rjw@rjwysocki.net> - 2016-07-12 00:40 +0200
        Re: [Query] Preemption (hogging) of the work handler Viresh Kumar <viresh.kumar@linaro.org> - 2016-07-12 00:50 +0200
          Re: [Query] Preemption (hogging) of the work handler "Rafael J. Wysocki" <rjw@rjwysocki.net> - 2016-07-12 14:30 +0200
            Re: [Query] Preemption (hogging) of the work handler Viresh Kumar <viresh.kumar@linaro.org> - 2016-07-12 15:10 +0200
              Re: [Query] Preemption (hogging) of the work handler Petr Mladek <pmladek@suse.com> - 2016-07-12 16:00 +0200
                Re: [Query] Preemption (hogging) of the work handler Viresh Kumar <viresh.kumar@linaro.org> - 2016-07-12 16:10 +0200
      Re: [Query] Preemption (hogging) of the work handler Viresh Kumar <viresh.kumar@linaro.org> - 2016-07-12 00:40 +0200
        Re: [Query] Preemption (hogging) of the work handler Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-07-12 11:40 +0200
          Re: [Query] Preemption (hogging) of the work handler Petr Mladek <pmladek@suse.com> - 2016-07-12 15:00 +0200
            Re: [Query] Preemption (hogging) of the work handler Viresh Kumar <viresh.kumar@linaro.org> - 2016-07-12 15:20 +0200
              Re: [Query] Preemption (hogging) of the work handler Viresh Kumar <viresh.kumar@linaro.org> - 2016-07-12 19:20 +0200
                Re: [Query] Preemption (hogging) of the work handler Viresh Kumar <viresh.kumar@linaro.org> - 2016-07-12 22:10 +0200
                Re: [Query] Preemption (hogging) of the work handler "Rafael J. Wysocki" <rafael@kernel.org> - 2016-07-12 22:10 +0200
                Re: [Query] Preemption (hogging) of the work handler Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-07-13 09:10 +0200
                  Re: [Query] Preemption (hogging) of the work handler "Rafael J. Wysocki" <rafael@kernel.org> - 2016-07-13 14:10 +0200
                    Re: [Query] Preemption (hogging) of the work handler Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2016-07-13 15:00 +0200
                      Re: [Query] Preemption (hogging) of the work handler "Rafael J. Wysocki" <rafael@kernel.org> - 2016-07-13 15:30 +0200
            Re: [Query] Preemption (hogging) of the work handler Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2016-07-12 16:10 +0200
              Re: [Query] Preemption (hogging) of the work handler Viresh Kumar <viresh.kumar@linaro.org> - 2016-07-15 02:00 +0200
                Re: [Query] Preemption (hogging) of the work handler Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2016-07-15 15:20 +0200
                  Re: [Query] Preemption (hogging) of the work handler Viresh Kumar <viresh.kumar@linaro.org> - 2016-07-15 18:00 +0200
        Re: [Query] Preemption (hogging) of the work handler Viresh Kumar <viresh.kumar@linaro.org> - 2016-07-13 01:30 +0200
          Re: [Query] Preemption (hogging) of the work handler Viresh Kumar <viresh.kumar@linaro.org> - 2016-07-13 02:20 +0200
          Re: [Query] Preemption (hogging) of the work handler Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-07-13 07:50 +0200
            Re: [Query] Preemption (hogging) of the work handler Viresh Kumar <viresh.kumar@linaro.org> - 2016-07-13 17:50 +0200
              Re: [Query] Preemption (hogging) of the work handler "Rafael J. Wysocki" <rafael@kernel.org> - 2016-07-14 01:10 +0200
                Re: [Query] Preemption (hogging) of the work handler Viresh Kumar <viresh.kumar@linaro.org> - 2016-07-14 01:20 +0200
                  Re: [Query] Preemption (hogging) of the work handler Greg Kroah-Hartman <gregkh@linuxfoundation.org> - 2016-07-14 01:40 +0200
              Re: [Query] Preemption (hogging) of the work handler Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-07-14 03:00 +0200
                Re: [Query] Preemption (hogging) of the work handler "Rafael J. Wysocki" <rafael@kernel.org> - 2016-07-14 03:10 +0200
                  Re: [Query] Preemption (hogging) of the work handler Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-07-14 03:40 +0200
                    Re: [Query] Preemption (hogging) of the work handler Viresh Kumar <viresh.kumar@linaro.org> - 2016-07-15 00:00 +0200
                Re: [Query] Preemption (hogging) of the work handler Viresh Kumar <viresh.kumar@linaro.org> - 2016-07-15 00:00 +0200
            Re: [Query] Preemption (hogging) of the work handler Jan Kara <jack@suse.cz> - 2016-07-14 16:20 +0200
              Re: [Query] Preemption (hogging) of the work handler "Rafael J. Wysocki" <rjw@rjwysocki.net> - 2016-07-14 16:30 +0200
                Re: [Query] Preemption (hogging) of the work handler Jan Kara <jack@suse.cz> - 2016-07-14 16:40 +0200
                  Re: [Query] Preemption (hogging) of the work handler "Rafael J. Wysocki" <rjw@rjwysocki.net> - 2016-07-14 16:50 +0200
                    Re: [Query] Preemption (hogging) of the work handler Jan Kara <jack@suse.cz> - 2016-07-14 17:00 +0200
                      Re: [Query] Preemption (hogging) of the work handler Viresh Kumar <viresh.kumar@linaro.org> - 2016-07-15 00:20 +0200
              Re: [Query] Preemption (hogging) of the work handler Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2016-07-14 16:40 +0200
                Re: [Query] Preemption (hogging) of the work handler Jan Kara <jack@suse.cz> - 2016-07-14 17:10 +0200
              Re: [Query] Preemption (hogging) of the work handler Viresh Kumar <viresh.kumar@linaro.org> - 2016-07-15 00:20 +0200
                Re: [Query] Preemption (hogging) of the work handler Jan Kara <jack@suse.cz> - 2016-07-18 13:10 +0200
                  Re: [Query] Preemption (hogging) of the work handler "Rafael J. Wysocki" <rjw@rjwysocki.net> - 2016-07-18 13:50 +0200
    Re: [Query] Preemption (hogging) of the work handler Viresh Kumar <viresh.kumar@linaro.org> - 2016-07-11 21:10 +0200

Page 2 of 3 — ← Prev page 1 [2] 3  Next page →

#1443823

Sorry, but I failed to do any testing on this and answer the questions you
raise. But I saw this again today and here are some important points.

On 12-07-16, 23:03, Sergey Senozhatsky wrote:
> so, I'm looking at this thing now:
> 
> : [   12.874909] sched: RT throttling activated for rt_rq ffffffc0ac13fcd0 (cpu 0)
> : [   12.874909] potential CPU hogs:
> : [   12.874909]  printk (292)
> 
> so it's either cond_resched() does not reshed, keeping printk kthread
> active, which, however, upsets the sched and triggers throttling (umm, what);
> 
> or we, somehow, have `console_may_schedule == 0' in this final console_unlock(),
> so cond_resched() never happens.
> 
> I'm looking at mainline 3.10, tho.
> 
> Viresh, can you verify if we can do cond_resched() from console_unlock()
> (console_may_schedule != 0) ?

I have hit this throttling issue twice and both were under the same
circumstances. Explaining in case it can help us debug it further :)

- Happens during early boot of the phone, ~10 seconds.
- Userspace noted that there are some issues with Android filesystem, like
  /system/bin/sh not found and so it says:

        init: cannot find '/system/bin/sh' (No such file or directory),
        disabling 'console'

- Userspace noticed that something is wrong and its good to reboot phone in
  another mode.
- But before that it dumps the kernel-messages from last boot and the prints
  looked like this:

  [   12.805180] [    7.919623] **Some Kernel Messages here**

Double time-stamp here, because one was already present in the last KMSG (logs
from previous boot).

After around 100 lines got printed, we had this throttling messages (without the
double timestamp), and we continue to print things after it as well.

-- 
viresh

[toc] | [prev] | [next] | [standalone]

#1444307

Hello,

On (07/14/16 16:52), Viresh Kumar wrote:
> On 12-07-16, 23:03, Sergey Senozhatsky wrote:
> > so, I'm looking at this thing now:
> > 
> > : [   12.874909] sched: RT throttling activated for rt_rq ffffffc0ac13fcd0 (cpu 0)
> > : [   12.874909] potential CPU hogs:
> > : [   12.874909]  printk (292)
> > 
[..]
> - But before that it dumps the kernel-messages from last boot and the prints
>   looked like this:

kmsg_dump()? a wild guess... any chance that you kmsg dumper iterates
log_buf records under logbuf_lock long enough to cause throttling on
other CPU, because printk_kthread is simply has to spin on logbuf_lock?

something like

CPU0						CPU1

console_unlock()				kmsg_dump()
{						{
							kmsg_dump_get_buffer()
							{
								spin_lock(&logbuf_lock)

	spin_lock(&logbuf_lock)					while (....) {
							 	^^^^^^^^^^^^^^ long enough
									...
								}
								spin_unlock(&logbuf_lock)
							}
	....					}
	spin_unlock(&logbuf_lock)

	call_console_drivers()

	cond_resched()
		RT throttling
			printk_deferred("RT throttling")
}

	-ss


>   [   12.805180] [    7.919623] **Some Kernel Messages here**
> 
> Double time-stamp here, because one was already present in the last KMSG (logs
> from previous boot).
> 
> After around 100 lines got printed, we had this throttling messages (without the
> double timestamp), and we continue to print things after it as well.
> 
> -- 
> viresh
> 

[toc] | [prev] | [next] | [standalone]

#1444404

On 15-07-16, 22:11, Sergey Senozhatsky wrote:
> Hello,
> 
> On (07/14/16 16:52), Viresh Kumar wrote:
> > On 12-07-16, 23:03, Sergey Senozhatsky wrote:
> > > so, I'm looking at this thing now:
> > > 
> > > : [   12.874909] sched: RT throttling activated for rt_rq ffffffc0ac13fcd0 (cpu 0)
> > > : [   12.874909] potential CPU hogs:
> > > : [   12.874909]  printk (292)
> > > 
> [..]
> > - But before that it dumps the kernel-messages from last boot and the prints
> >   looked like this:
> 
> kmsg_dump()?

I am happy that this code is available in open :)

https://chromium.googlesource.com/aosp/platform/system/core/+/master/healthd/healthd_mode_charger.cpp#194

> a wild guess... any chance that you kmsg dumper iterates
> log_buf records under logbuf_lock long enough to cause throttling on
> other CPU, because printk_kthread is simply has to spin on logbuf_lock?

Hmm, I am not sure of it yet.

-- 
viresh

[toc] | [prev] | [next] | [standalone]

#1441911

On 11-07-16, 15:35, Viresh Kumar wrote:
> Sometimes, the platform doesn't come back after suspend. I have tried
> enabling no-console-suspend and the last line it prints is:
> 
>         Disabling non-boot CPUs
> 
> And nothing after that at all. We have to forcefully reboot the phone
> after that. Moving the prints to they synchronous way (using
> echo 1 > /sys/module/printk/parameters/synchronous), fixes that issue.
> 
> So, the asynchronous printing have a issue that only we are hitting.
> It looks like that all the CPUs are gone except CPU0 and that CPU is
> hogged by the printk thread to print stuff as well as to suspend the
> system, and something eventually gets wrong.
> 
> I am only using the 3 patches from V12 version of the series.

Okay, we have tracked this BUG and its really interesting.

I hacked the platform's serial driver to implement a putchar() routine
that simply writes to the FIFO in polling mode, that helped us in
tracing on where we are going wrong.

The problem is that we are running asynchronous printks and we call
wake_up_process() from the last running CPU which has disabled
interrupts. That takes us to: try_to_wake_up().

In our case the CPU gets deadlocked on this line in try_to_wake_up().

        raw_spin_lock_irqsave(&p->pi_lock, flags);

I will explain how:

The try_to_wake_up() function takes us through the scheduler code (RT
sched), to the hrtimer code, where we eventually call ktime_get() (for
the MONOTONIC clock used for hrtimer). And this function has this:

        WARN_ON(timekeeping_suspended);

This starts another printk while we are in the middle of
wake_up_process() and the CPU tries to take the above lock again and
gets stuck there :)

This doesn't happen everytime because we don't always call ktime_get()
and it is called only if hrtimer_active() returns false.

This happened because of a WARN_ON() but it can happen anyway. Think
about this case:

- offline all CPUs, except 0
- call any routine that prints messages after disabling interrupts,
  etc.
- If any of the function within wake_up_process() does a print, we are
  screwed.

So the thing is that we can't really call wake_up_process() in cases
where the last CPU disables interrupts. And that's why my fixup patch
(which moved to synchronous prints after suspend) really works.

@Jan and Sergey: I would expect a patch from you guys to fix this
properly :)

Maybe something more in can_print_async() routine, like:

only-one-cpu-online + irqs_disabled()

or whatever.

-- 
viresh

[toc] | [prev] | [next] | [standalone]

#1441926

On 12-07-16, 16:19, Viresh Kumar wrote:
> Okay, we have tracked this BUG and its really interesting.
> 
> I hacked the platform's serial driver to implement a putchar() routine
> that simply writes to the FIFO in polling mode, that helped us in
> tracing on where we are going wrong.
> 
> The problem is that we are running asynchronous printks and we call
> wake_up_process() from the last running CPU which has disabled
> interrupts. That takes us to: try_to_wake_up().
> 
> In our case the CPU gets deadlocked on this line in try_to_wake_up().
> 
>         raw_spin_lock_irqsave(&p->pi_lock, flags);
> 
> I will explain how:
> 
> The try_to_wake_up() function takes us through the scheduler code (RT
> sched), to the hrtimer code, where we eventually call ktime_get() (for
> the MONOTONIC clock used for hrtimer). And this function has this:
> 
>         WARN_ON(timekeeping_suspended);
> 
> This starts another printk while we are in the middle of
> wake_up_process() and the CPU tries to take the above lock again and
> gets stuck there :)
> 
> This doesn't happen everytime because we don't always call ktime_get()
> and it is called only if hrtimer_active() returns false.
> 
> This happened because of a WARN_ON() but it can happen anyway. Think
> about this case:
> 
> - offline all CPUs, except 0
> - call any routine that prints messages after disabling interrupts,
>   etc.
> - If any of the function within wake_up_process() does a print, we are
>   screwed.
> 
> So the thing is that we can't really call wake_up_process() in cases
> where the last CPU disables interrupts. And that's why my fixup patch
> (which moved to synchronous prints after suspend) really works.

Actually, any printk done from wake_up_process() will hit this, even
if all the others CPUs are up as well :)

Its only BUG_ON() which has special handling in printk, and so we
print that safely.

-- 
viresh

[toc] | [prev] | [next] | [standalone]

#1442001

Cc Petr Mladek.

On (07/12/16 16:19), Viresh Kumar wrote:
[..]
> Okay, we have tracked this BUG and its really interesting.

good find!

> I hacked the platform's serial driver to implement a putchar() routine
> that simply writes to the FIFO in polling mode, that helped us in
> tracing on where we are going wrong.
> 
> The problem is that we are running asynchronous printks and we call
> wake_up_process() from the last running CPU which has disabled
> interrupts. That takes us to: try_to_wake_up().
> 
> In our case the CPU gets deadlocked on this line in try_to_wake_up().
> 
>         raw_spin_lock_irqsave(&p->pi_lock, flags);

yeah, printk() can't handle these types of recursion. it can prevent
printk() calls issued from within the logbuf_lock spinlock section,
with some limitations:

	if (unlikely(logbuf_cpu == smp_processor_id())) {
		recursion_bug = true;
		return;
	}

	raw_spin_lock(&logbuf_lock);
	logbuf_cpu = this_cpu;
		...
	logbuf_cpu = UINT_MAX;
	raw_spin_unlock(&logbuf_lock);

so should, for instance, raw_spin_unlock() generate spin_dump(), printk()
will blow up (both sync and async), because logbuf_cpu is already reset.
it may look that async printk added another source of recursion - wake_up().
but, apparently, this is not exactly correct. because there is already a
wake_up() call in console_unlock() - up().

	printk()
	 if (logbuf_cpu == smp_processor_id())
		return;

         raw_spin_lock(&logbuf_lock);
	 logbuf_cpu = this_cpu;
	 ...
	 logbuf_cpu = UINT_MAX;
         raw_spin_unlock(&logbuf_lock);

	 console_trylock()
	   raw_spin_lock_irqsave(&sem->lock)      << ***
	   raw_spin_unlock_irqsave(&sem->lock)    << ***

	 console_unlock()
          up()
	   raw_spin_lock_irqsave(&sem->lock)  << ***
	    __up()
	     wake_up_process()
	      try_to_wake_up()  << *** in may places


*** a printk() call from here will kill the system. either it will
recurse printk(), or spin forever in 'nested' printk() on one of
the already taken spin locks.

I had an idea of waking up a printk_kthread under logbuf_lock,
so `logbuf_cpu == smp_processor_id()' test would help here. But
it turned out to introduce a regression in printk() behaviour.
apart from that, it didn't fix any of the existing recursion
printks.

there is printk_deferred() printk that is supposed to be used for
printing under scheduler locks, but it won't help in all of the cases.

printk() has many issues.

> I will explain how:
> 
> The try_to_wake_up() function takes us through the scheduler code (RT
> sched), to the hrtimer code, where we eventually call ktime_get() (for
> the MONOTONIC clock used for hrtimer). And this function has this:
> 
>         WARN_ON(timekeeping_suspended);
> 
> This starts another printk while we are in the middle of
> wake_up_process() and the CPU tries to take the above lock again and
> gets stuck there :)
> 
> This doesn't happen everytime because we don't always call ktime_get()
> and it is called only if hrtimer_active() returns false.
> 
> This happened because of a WARN_ON() but it can happen anyway. Think
> about this case:
> 
> - offline all CPUs, except 0
> - call any routine that prints messages after disabling interrupts,
>   etc.
> - If any of the function within wake_up_process() does a print, we are
>   screwed.
> 
> So the thing is that we can't really call wake_up_process() in cases
> where the last CPU disables interrupts. And that's why my fixup patch
> (which moved to synchronous prints after suspend) really works.
> 
> @Jan and Sergey: I would expect a patch from you guys to fix this
> properly :)
> 
> Maybe something more in can_print_async() routine, like:
> 
> only-one-cpu-online + irqs_disabled()
> 

right. adding only (num_online_cpus() > 1) check to can_printk_async()
*in theory* can break some cases. for example, SMP system, with only
one online CPU, active rt_sched throttling (not necessarily because of
printk kthread, any other task will do), and some of interrupts services
by CPU0 keep calling printk(), so deferred printk IRQ will stay busy:

	echo 0 > /sys/..../cpu{1..NR_CPUS}/online  # only CPU0 is active

	CPU0
	sched()
	 printk_deferred()
				IRQ
				wake_up_klogd_work_func()
					console_trylock()
						console_unlock()

								IRQ
								printk()

								IRQ
								printk()
								....
								IRQ
								printk()
								...

						  console_sem_up()
						  return

with async printk here we can offload printing from IRQ.

the warning that you see is WARN_ON(timekeeping_suspended), so we have
timekeeping_suspended, checking for irqs_disabled() is a _bit_ non-intuitive,
I think, but in the existing scheme of things can work (at least tick_suspend()
comment suggests so). correct me if I'm wrong.


so... I think we can switch to sync printk mode in suspend_console() and
enable async printk from resume_console(). IOW, suspend/kexec are now
executed under sync printk mode.

we already call console_unlock() during suspend, which is synchronous,
many times (e.g. console_cpu_notify()).


something like below, perhaps. will this work for you?

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

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index bbb4180..786690e 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -288,6 +288,11 @@ static u32 log_buf_len = __LOG_BUF_LEN;
 
 /* Control whether printing to console must be synchronous. */
 static bool __read_mostly printk_sync = true;
+/*
+ * Force sync printk mode during suspend/kexec, regardless whether
+ * console_suspend_enabled permits console suspend.
+ */
+static bool __read_mostly force_printk_sync;
 /* Printing kthread for async printk */
 static struct task_struct *printk_kthread;
 /* When `true' printing thread has messages to print */
@@ -295,7 +300,7 @@ static bool printk_kthread_need_flush_console;
 
 static inline bool can_printk_async(void)
 {
-	return !printk_sync && printk_kthread;
+	return !printk_sync && printk_kthread && !force_printk_sync;
 }
 
 /* Return log buffer address */
@@ -2027,6 +2032,7 @@ static bool suppress_message_printing(int level) { return false; }
 
 /* Still needs to be defined for users */
 DEFINE_PER_CPU(printk_func_t, printk_func);
+static bool __read_mostly force_printk_sync;
 
 #endif /* CONFIG_PRINTK */
 
@@ -2163,6 +2169,8 @@ MODULE_PARM_DESC(console_suspend, "suspend console during suspend"
  */
 void suspend_console(void)
 {
+	force_printk_sync = true;
+
 	if (!console_suspend_enabled)
 		return;
 	printk("Suspending console(s) (use no_console_suspend to debug)\n");
@@ -2173,6 +2181,8 @@ void suspend_console(void)
 
 void resume_console(void)
 {
+	force_printk_sync = false;
+
 	if (!console_suspend_enabled)
 		return;
 	down_console_sem();
-- 
2.9.0.rc1

[toc] | [prev] | [next] | [standalone]

#1442563

On 13-07-16, 14:45, Sergey Senozhatsky wrote:
> On (07/12/16 16:19), Viresh Kumar wrote:
> [..]
> > Okay, we have tracked this BUG and its really interesting.
> 
> good find!
> 
> > I hacked the platform's serial driver to implement a putchar() routine
> > that simply writes to the FIFO in polling mode, that helped us in
> > tracing on where we are going wrong.
> > 
> > The problem is that we are running asynchronous printks and we call
> > wake_up_process() from the last running CPU which has disabled
> > interrupts. That takes us to: try_to_wake_up().
> > 
> > In our case the CPU gets deadlocked on this line in try_to_wake_up().
> > 
> >         raw_spin_lock_irqsave(&p->pi_lock, flags);
> 
> yeah, printk() can't handle these types of recursion. it can prevent
> printk() calls issued from within the logbuf_lock spinlock section,
> with some limitations:
> 
> 	if (unlikely(logbuf_cpu == smp_processor_id())) {
> 		recursion_bug = true;
> 		return;
> 	}
> 
> 	raw_spin_lock(&logbuf_lock);
> 	logbuf_cpu = this_cpu;
> 		...
> 	logbuf_cpu = UINT_MAX;
> 	raw_spin_unlock(&logbuf_lock);
> 
> so should, for instance, raw_spin_unlock() generate spin_dump(), printk()
> will blow up (both sync and async), because logbuf_cpu is already reset.

I see.

> it may look that async printk added another source of recursion - wake_up().
> but, apparently, this is not exactly correct. because there is already a
> wake_up() call in console_unlock() - up().
> 
> 	printk()
> 	 if (logbuf_cpu == smp_processor_id())
> 		return;
> 
>          raw_spin_lock(&logbuf_lock);
> 	 logbuf_cpu = this_cpu;
> 	 ...
> 	 logbuf_cpu = UINT_MAX;
>          raw_spin_unlock(&logbuf_lock);
> 
> 	 console_trylock()
> 	   raw_spin_lock_irqsave(&sem->lock)      << ***
> 	   raw_spin_unlock_irqsave(&sem->lock)    << ***
> 
> 	 console_unlock()
>           up()
> 	   raw_spin_lock_irqsave(&sem->lock)  << ***
> 	    __up()
> 	     wake_up_process()
> 	      try_to_wake_up()  << *** in may places
> 
> 
> *** a printk() call from here will kill the system. either it will
> recurse printk(), or spin forever in 'nested' printk() on one of
> the already taken spin locks.

So, in case you are asked for similar issues (system hang), we should
first doubt on recursive prints from somewhere :)

:)

> I had an idea of waking up a printk_kthread under logbuf_lock,
> so `logbuf_cpu == smp_processor_id()' test would help here. But
> it turned out to introduce a regression in printk() behaviour.
> apart from that, it didn't fix any of the existing recursion
> printks.
> 
> there is printk_deferred() printk that is supposed to be used for
> printing under scheduler locks, but it won't help in all of the cases.
> 
> printk() has many issues.

Yeah, that's why we are all here :)

> right. adding only (num_online_cpus() > 1) check to can_printk_async()
> *in theory* can break some cases. for example, SMP system, with only
> one online CPU, active rt_sched throttling (not necessarily because of
> printk kthread, any other task will do), and some of interrupts services
> by CPU0 keep calling printk(), so deferred printk IRQ will stay busy:

Right.

> 	echo 0 > /sys/..../cpu{1..NR_CPUS}/online  # only CPU0 is active
> 
> 	CPU0
> 	sched()
> 	 printk_deferred()
> 				IRQ
> 				wake_up_klogd_work_func()
> 					console_trylock()
> 						console_unlock()
> 
> 								IRQ
> 								printk()
> 
> 								IRQ
> 								printk()
> 								....
> 								IRQ
> 								printk()
> 								...
> 
> 						  console_sem_up()
> 						  return
> 
> with async printk here we can offload printing from IRQ.
> 
> the warning that you see is WARN_ON(timekeeping_suspended), so we have
> timekeeping_suspended

Right.

> checking for irqs_disabled() is a _bit_ non-intuitive,
> I think, but in the existing scheme of things can work (at least tick_suspend()
> comment suggests so). correct me if I'm wrong.
> 
> 
> so... I think we can switch to sync printk mode in suspend_console() and
> enable async printk from resume_console(). IOW, suspend/kexec are now
> executed under sync printk mode.
> 
> we already call console_unlock() during suspend, which is synchronous,
> many times (e.g. console_cpu_notify()).
> 
> 
> something like below, perhaps. will this work for you?

Maybe not, as this can still lead to the original bug we were all
chasing. This may hog some other CPU if we are doing excessive
printing in suspend :(

suspend_console() is called quite early, so for example in my case we
do lots of printing during suspend (not from the suspend thread, but
an IRQ handled by the USB subsystem, which removes a bus with help of
some other thread probably).

That is why my Hacky patch tried to do it after devices are removed
and irqs are disabled, but before syscore users are suspended (and
timekeeping is one of them). And so it fixes it for me completely.

IOW, we should switch back to synchronous printing after disabling
interrupts on the last running CPU.

And I of course agree with Rafael that we would need something similar
in Hibernation code path as well, if we choose to fix it my way.

-- 
viresh

[toc] | [prev] | [next] | [standalone]

#1442937

On Wed, Jul 13, 2016 at 5:39 PM, Viresh Kumar <viresh.kumar@linaro.org> wrote:
> On 13-07-16, 14:45, Sergey Senozhatsky wrote:
>> On (07/12/16 16:19), Viresh Kumar wrote:

[cut]

>>
>> something like below, perhaps. will this work for you?
>
> Maybe not, as this can still lead to the original bug we were all
> chasing. This may hog some other CPU if we are doing excessive
> printing in suspend :(

How can it hog that CPU, exactly?

> suspend_console() is called quite early, so for example in my case we
> do lots of printing during suspend (not from the suspend thread, but
> an IRQ handled by the USB subsystem, which removes a bus with help of
> some other thread probably).

Why doing a lot of printing from an IRQ is not regarded as a bug?

Are all of those messages printed actually useful?

> That is why my Hacky patch tried to do it after devices are removed
> and irqs are disabled, but before syscore users are suspended (and
> timekeeping is one of them). And so it fixes it for me completely.
>
> IOW, we should switch back to synchronous printing after disabling
> interrupts on the last running CPU.
>
> And I of course agree with Rafael that we would need something similar
> in Hibernation code path as well, if we choose to fix it my way.

Well, the patch proposed by Sergey is sufficient to fix the deadlock
issue and it is not clear that anything more needs to be done.

My suggestion, then, would be to use this patch to start with and see
if things really go worse then.

Thanks,
Rafael

[toc] | [prev] | [next] | [standalone]

#1442938

On 14-07-16, 01:08, Rafael J. Wysocki wrote:
> On Wed, Jul 13, 2016 at 5:39 PM, Viresh Kumar <viresh.kumar@linaro.org> wrote:
> > Maybe not, as this can still lead to the original bug we were all
> > chasing. This may hog some other CPU if we are doing excessive
> > printing in suspend :(
> 
> How can it hog that CPU, exactly?

Not *that* CPU, but any of the CPUs. Because we are moving back to
synchronous printing, any CPU which is doing a lot of printing, may
end up spending all its time in the print-loop (as the original
problem we had).

> > suspend_console() is called quite early, so for example in my case we
> > do lots of printing during suspend (not from the suspend thread, but
> > an IRQ handled by the USB subsystem, which removes a bus with help of
> > some other thread probably).
> 
> Why doing a lot of printing from an IRQ is not regarded as a bug?

We aren't doing it in Interrupt Context or with interrupts disabled,
but perhaps in the kthread managed by usb hub core.

But, I am not only talking about my platform's printing issues, but
the idea behind the patches that Sergey and Jan are working on. If we
move back to synchronous printing before starting to suspend the
devices, we may have the same problem again that we were trying to
solve.

> Are all of those messages printed actually useful?

Hmm, maybe not. But that's not the point I was trying to raise, as I
earlier mentioned :)

We have a problem with asynchronous printing after disabling
interrupts on the last running CPU, and we are trying to disable that
from suspend_console(), because we already have a function to call
this from.

> > That is why my Hacky patch tried to do it after devices are removed
> > and irqs are disabled, but before syscore users are suspended (and
> > timekeeping is one of them). And so it fixes it for me completely.
> >
> > IOW, we should switch back to synchronous printing after disabling
> > interrupts on the last running CPU.
> >
> > And I of course agree with Rafael that we would need something similar
> > in Hibernation code path as well, if we choose to fix it my way.
> 
> Well, the patch proposed by Sergey is sufficient to fix the deadlock
> issue and it is not clear that anything more needs to be done.
> 
> My suggestion, then, would be to use this patch to start with and see
> if things really go worse then.

Sure, I am just saying that theoretically, we can still have the CPU
hog problem that we all started with :)

-- 
viresh

[toc] | [prev] | [next] | [standalone]

#1442942

On Wed, Jul 13, 2016 at 04:18:58PM -0700, Viresh Kumar wrote:
> > Are all of those messages printed actually useful?
> 
> Hmm, maybe not. But that's not the point I was trying to raise, as I
> earlier mentioned :)
> 
> We have a problem with asynchronous printing after disabling
> interrupts on the last running CPU, and we are trying to disable that
> from suspend_console(), because we already have a function to call
> this from.

Note, this problem has also been seen in "the wild" in a number of
3.10-based systems where a printk message happens right when suspend is
happening.  If we are unlucky, it hits, causing a watchdog to trigger
and the system is reset.  My personal phone happens to be one of those
"unlucky" ones and is reset every other day or so due to this bug :(

So yes, lots of printk() messages will cause this to be hit more often,
like in the system that Viresh is working on here.  But it will also
trigger on "normal" systems as well, just much more infrequently.

thanks,

greg k-h

[toc] | [prev] | [next] | [standalone]

#1442970

Hello,

On (07/13/16 08:39), Viresh Kumar wrote:
[..]
> Maybe not, as this can still lead to the original bug we were all
> chasing. This may hog some other CPU if we are doing excessive
> printing in suspend :(

excessive printing is just part of the problem here. if we cab cond_resched()
in console_unlock() (IOW, we execute console_unlock() with preemption and
interrupts enabled) then everything must be ok, and *from printing POV* there
is no difference whether it's printk_kthread or anything else in this case.
the difference jumps in when original console_unlock() is executed with
preemption/irq disabled, then offloading it to schedulable printk_kthread is
the right thing.

> suspend_console() is called quite early, so for example in my case we
> do lots of printing during suspend (not from the suspend thread, but
> an IRQ handled by the USB subsystem, which removes a bus with help of
> some other thread probably).

a silly question -- can we suspend consoles later?

part of suspend/hibernation is cpu_down(), which lands in console_cpu_notify(),
that does synchronous printing for every CPU taken down:

static int console_cpu_notify(struct notifier_block *self,
	unsigned long action, void *hcpu)
{
	switch (action) {
	case CPU_ONLINE:
	case CPU_DEAD:
	case CPU_DOWN_FAILED:
	case CPU_UP_CANCELED:
		console_lock();
		console_unlock();
		^^^^^^^^^^^^^^
	}
	return NOTIFY_OK;
}

console_unlock() is synchronous (I posted a very early draft patch that makes
it asynchronous, but that's a future work). so if there is a ton of printk()-s,
then console_unlock() will print it, 100% guaranteed. even if printk_kthread
is doing the printing job at the moment, cpu down path will wait for it to
stop, lock the console semaphore, and got to console_unlock() printing loop.

in printk that you have posted, that will happen not only for CPU_DEAD,
but for CPU_DYING as well (possibly, there is a /* invoked with preemption
disabled, so defer */ comment, so may be you never endup doing direct
printk there, but then you schedule a console_unlock() work).

> That is why my Hacky patch tried to do it after devices are removed
> and irqs are disabled, but before syscore users are suspended (and
> timekeeping is one of them). And so it fixes it for me completely.
> 
> IOW, we should switch back to synchronous printing after disabling
> interrupts on the last running CPU.
> 
> And I of course agree with Rafael that we would need something similar
> in Hibernation code path as well, if we choose to fix it my way.

suspend/hibernation/kexec - all covered by this patch.

	-ss

[toc] | [prev] | [next] | [standalone]

#1442974

On Thu, Jul 14, 2016 at 2:55 AM, Sergey Senozhatsky
<sergey.senozhatsky.work@gmail.com> wrote:
> Hello,
>
> On (07/13/16 08:39), Viresh Kumar wrote:
> [..]
>> Maybe not, as this can still lead to the original bug we were all
>> chasing. This may hog some other CPU if we are doing excessive
>> printing in suspend :(
>
> excessive printing is just part of the problem here. if we cab cond_resched()
> in console_unlock() (IOW, we execute console_unlock() with preemption and
> interrupts enabled) then everything must be ok, and *from printing POV* there
> is no difference whether it's printk_kthread or anything else in this case.
> the difference jumps in when original console_unlock() is executed with
> preemption/irq disabled, then offloading it to schedulable printk_kthread is
> the right thing.
>
>> suspend_console() is called quite early, so for example in my case we
>> do lots of printing during suspend (not from the suspend thread, but
>> an IRQ handled by the USB subsystem, which removes a bus with help of
>> some other thread probably).
>
> a silly question -- can we suspend consoles later?

Not really and I'm not sure how that would help?

[toc] | [prev] | [next] | [standalone]

#1442986

On (07/14/16 03:09), Rafael J. Wysocki wrote:
> On Thu, Jul 14, 2016 at 2:55 AM, Sergey Senozhatsky
> <sergey.senozhatsky.work@gmail.com> wrote:
> > Hello,
> >
> > On (07/13/16 08:39), Viresh Kumar wrote:
> > [..]
> >> Maybe not, as this can still lead to the original bug we were all
> >> chasing. This may hog some other CPU if we are doing excessive
> >> printing in suspend :(
> >
> > excessive printing is just part of the problem here. if we cab cond_resched()
> > in console_unlock() (IOW, we execute console_unlock() with preemption and
> > interrupts enabled) then everything must be ok, and *from printing POV* there
> > is no difference whether it's printk_kthread or anything else in this case.
> > the difference jumps in when original console_unlock() is executed with
> > preemption/irq disabled, then offloading it to schedulable printk_kthread is
> > the right thing.
> >
> >> suspend_console() is called quite early, so for example in my case we
> >> do lots of printing during suspend (not from the suspend thread, but
> >> an IRQ handled by the USB subsystem, which removes a bus with help of
> >> some other thread probably).
> >
> > a silly question -- can we suspend consoles later?
> 
> Not really and I'm not sure how that would help?

it wouldn't really, this silly question was not directly related to the
deadlock we are discussing here but to Viresh's argument that later stages
of suspending/hibernation seem to printk many messages in sync mode. so I
thought that there might be a small benefit in suspending consoles later,
as far as I understand, Viresh has `no_console_suspend' anyway. other
than that, I tend to stick to the approach of switching to sync mode from
suspend_console().

thanks for your late night reply!

	-ss

[toc] | [prev] | [next] | [standalone]

#1443801

On 14-07-16, 10:32, Sergey Senozhatsky wrote:
> it wouldn't really, this silly question was not directly related to the
> deadlock we are discussing here but to Viresh's argument that later stages
> of suspending/hibernation seem to printk many messages in sync mode. so I
> thought that there might be a small benefit in suspending consoles later,
> as far as I understand, Viresh has `no_console_suspend' anyway. other

That option is enabled only for testing though :)

> than that, I tend to stick to the approach of switching to sync mode from
> suspend_console().

I actually need to test it out as well :)

-- 
viresh

[toc] | [prev] | [next] | [standalone]

#1443802

On 14-07-16, 09:55, Sergey Senozhatsky wrote:
> excessive printing is just part of the problem here. if we cab cond_resched()
> part of suspend/hibernation is cpu_down(), which lands in console_cpu_notify(),
> that does synchronous printing for every CPU taken down:
> 
> static int console_cpu_notify(struct notifier_block *self,
> 	unsigned long action, void *hcpu)
> {
> 	switch (action) {
> 	case CPU_ONLINE:
> 	case CPU_DEAD:
> 	case CPU_DOWN_FAILED:
> 	case CPU_UP_CANCELED:
> 		console_lock();
> 		console_unlock();
> 		^^^^^^^^^^^^^^
> 	}
> 	return NOTIFY_OK;
> }
> 
> console_unlock() is synchronous (I posted a very early draft patch that makes
> it asynchronous, but that's a future work). so if there is a ton of printk()-s,
> then console_unlock() will print it, 100% guaranteed. even if printk_kthread
> is doing the printing job at the moment, cpu down path will wait for it to
> stop, lock the console semaphore, and got to console_unlock() printing loop.

Hmm...

> in printk that you have posted, that will happen not only for CPU_DEAD,

It doesn't happen for CPU_DEAD right now as CONFIG_CONSOLE_FLUSH_ON_HOTPLUG
isn't enabled in my setup.

> but for CPU_DYING as well (possibly, there is a /* invoked with preemption
> disabled, so defer */ comment, so may be you never endup doing direct
> printk there, but then you schedule a console_unlock() work).

-- 
viresh

[toc] | [prev] | [next] | [standalone]

#1443476

On Wed 13-07-16 14:45:07, Sergey Senozhatsky wrote:
> Cc Petr Mladek.
> 
> On (07/12/16 16:19), Viresh Kumar wrote:
> [..]
> > Okay, we have tracked this BUG and its really interesting.
> 
> good find!
> 
> > I hacked the platform's serial driver to implement a putchar() routine
> > that simply writes to the FIFO in polling mode, that helped us in
> > tracing on where we are going wrong.
> > 
> > The problem is that we are running asynchronous printks and we call
> > wake_up_process() from the last running CPU which has disabled
> > interrupts. That takes us to: try_to_wake_up().
> > 
> > In our case the CPU gets deadlocked on this line in try_to_wake_up().
> > 
> >         raw_spin_lock_irqsave(&p->pi_lock, flags);
> 
> yeah, printk() can't handle these types of recursion. it can prevent
> printk() calls issued from within the logbuf_lock spinlock section,
> with some limitations:
> 
> 	if (unlikely(logbuf_cpu == smp_processor_id())) {
> 		recursion_bug = true;
> 		return;
> 	}
> 
> 	raw_spin_lock(&logbuf_lock);
> 	logbuf_cpu = this_cpu;
> 		...
> 	logbuf_cpu = UINT_MAX;
> 	raw_spin_unlock(&logbuf_lock);
> 
> so should, for instance, raw_spin_unlock() generate spin_dump(), printk()
> will blow up (both sync and async), because logbuf_cpu is already reset.
> it may look that async printk added another source of recursion - wake_up().
> but, apparently, this is not exactly correct. because there is already a
> wake_up() call in console_unlock() - up().
> 
> 	printk()
> 	 if (logbuf_cpu == smp_processor_id())
> 		return;
> 
>          raw_spin_lock(&logbuf_lock);
> 	 logbuf_cpu = this_cpu;
> 	 ...
> 	 logbuf_cpu = UINT_MAX;
>          raw_spin_unlock(&logbuf_lock);
> 
> 	 console_trylock()
> 	   raw_spin_lock_irqsave(&sem->lock)      << ***
> 	   raw_spin_unlock_irqsave(&sem->lock)    << ***
> 
> 	 console_unlock()
>           up()
> 	   raw_spin_lock_irqsave(&sem->lock)  << ***
> 	    __up()
> 	     wake_up_process()
> 	      try_to_wake_up()  << *** in may places
> 
> 
> *** a printk() call from here will kill the system. either it will
> recurse printk(), or spin forever in 'nested' printk() on one of
> the already taken spin locks.

Exactly. Calling printk() from certain parts of the kernel (like scheduler
code or timer code) has been always unsafe because printk itself uses these
parts and so it can lead to deadlocks. That's why printk_deffered() has
been introduced as you mention below.

And with sync printk the above deadlock doesn't trigger only by chance - if
there happened to be a waiter on console_sem while we suspend, the same
deadlock would trigger because up(&console_sem) will try to wake him up and
the warning in timekeeping code will cause recursive printk.

So I think your patch doesn't really address the real issue - it only
works around the particular WARN_ON(timekeeping_enabled) warning but if
there was a different warning in timekeeping code which would trigger, it
has a potential for causing recursive printk deadlock (and indeed we had
such issues previously - see e.g. 504d58745c9c "timer: Fix lock inversion
between hrtimer_bases.lock and scheduler locks").

So there are IMHO two issues here worth looking at:

1) I didn't find how a wakeup would would lead to calling to ktime_get() in
the current upstream kernel or even current RT kernel. Maybe this is a
problem specific to the 3.10 kernel you are using? If yes, we don't have to
do anything for current upstream AFAIU.

If I just missed how wakeup can call into ktime_get() in current upstream,
there is another question:

2) Is it OK that printk calls wakeup so late during suspend? I believe it
is but I'm neither scheduler nor suspend expert. If it is OK, and wakeup
can lead to ktime_get() in current upstream, then this contradicts the
check WARN_ON(timekeeping_suspended) in ktime_get() and something is wrong.

Adding Thomas to CC as timer / RT expert...

								Honza

> so... I think we can switch to sync printk mode in suspend_console() and
> enable async printk from resume_console(). IOW, suspend/kexec are now
> executed under sync printk mode.
> 
> we already call console_unlock() during suspend, which is synchronous,
> many times (e.g. console_cpu_notify()).
> 
> 
> something like below, perhaps. will this work for you?
> 
> ---
>  kernel/printk/printk.c | 12 +++++++++++-
>  1 file changed, 11 insertions(+), 1 deletion(-)
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index bbb4180..786690e 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -288,6 +288,11 @@ static u32 log_buf_len = __LOG_BUF_LEN;
>  
>  /* Control whether printing to console must be synchronous. */
>  static bool __read_mostly printk_sync = true;
> +/*
> + * Force sync printk mode during suspend/kexec, regardless whether
> + * console_suspend_enabled permits console suspend.
> + */
> +static bool __read_mostly force_printk_sync;
>  /* Printing kthread for async printk */
>  static struct task_struct *printk_kthread;
>  /* When `true' printing thread has messages to print */
> @@ -295,7 +300,7 @@ static bool printk_kthread_need_flush_console;
>  
>  static inline bool can_printk_async(void)
>  {
> -	return !printk_sync && printk_kthread;
> +	return !printk_sync && printk_kthread && !force_printk_sync;
>  }
>  
>  /* Return log buffer address */
> @@ -2027,6 +2032,7 @@ static bool suppress_message_printing(int level) { return false; }
>  
>  /* Still needs to be defined for users */
>  DEFINE_PER_CPU(printk_func_t, printk_func);
> +static bool __read_mostly force_printk_sync;
>  
>  #endif /* CONFIG_PRINTK */
>  
> @@ -2163,6 +2169,8 @@ MODULE_PARM_DESC(console_suspend, "suspend console during suspend"
>   */
>  void suspend_console(void)
>  {
> +	force_printk_sync = true;
> +
>  	if (!console_suspend_enabled)
>  		return;
>  	printk("Suspending console(s) (use no_console_suspend to debug)\n");
> @@ -2173,6 +2181,8 @@ void suspend_console(void)
>  
>  void resume_console(void)
>  {
> +	force_printk_sync = false;
> +
>  	if (!console_suspend_enabled)
>  		return;
>  	down_console_sem();
> -- 
> 2.9.0.rc1
> 
-- 
Jan Kara <jack@suse.com>
SUSE Labs, CR

[toc] | [prev] | [next] | [standalone]

#1443482

On Thursday, July 14, 2016 04:12:16 PM Jan Kara wrote:
> On Wed 13-07-16 14:45:07, Sergey Senozhatsky wrote:
> > Cc Petr Mladek.
> > 
> > On (07/12/16 16:19), Viresh Kumar wrote:
> > [..]
> > > Okay, we have tracked this BUG and its really interesting.
> > 
> > good find!
> > 
> > > I hacked the platform's serial driver to implement a putchar() routine
> > > that simply writes to the FIFO in polling mode, that helped us in
> > > tracing on where we are going wrong.
> > > 
> > > The problem is that we are running asynchronous printks and we call
> > > wake_up_process() from the last running CPU which has disabled
> > > interrupts. That takes us to: try_to_wake_up().
> > > 
> > > In our case the CPU gets deadlocked on this line in try_to_wake_up().
> > > 
> > >         raw_spin_lock_irqsave(&p->pi_lock, flags);
> > 
> > yeah, printk() can't handle these types of recursion. it can prevent
> > printk() calls issued from within the logbuf_lock spinlock section,
> > with some limitations:
> > 
> > 	if (unlikely(logbuf_cpu == smp_processor_id())) {
> > 		recursion_bug = true;
> > 		return;
> > 	}
> > 
> > 	raw_spin_lock(&logbuf_lock);
> > 	logbuf_cpu = this_cpu;
> > 		...
> > 	logbuf_cpu = UINT_MAX;
> > 	raw_spin_unlock(&logbuf_lock);
> > 
> > so should, for instance, raw_spin_unlock() generate spin_dump(), printk()
> > will blow up (both sync and async), because logbuf_cpu is already reset.
> > it may look that async printk added another source of recursion - wake_up().
> > but, apparently, this is not exactly correct. because there is already a
> > wake_up() call in console_unlock() - up().
> > 
> > 	printk()
> > 	 if (logbuf_cpu == smp_processor_id())
> > 		return;
> > 
> >          raw_spin_lock(&logbuf_lock);
> > 	 logbuf_cpu = this_cpu;
> > 	 ...
> > 	 logbuf_cpu = UINT_MAX;
> >          raw_spin_unlock(&logbuf_lock);
> > 
> > 	 console_trylock()
> > 	   raw_spin_lock_irqsave(&sem->lock)      << ***
> > 	   raw_spin_unlock_irqsave(&sem->lock)    << ***
> > 
> > 	 console_unlock()
> >           up()
> > 	   raw_spin_lock_irqsave(&sem->lock)  << ***
> > 	    __up()
> > 	     wake_up_process()
> > 	      try_to_wake_up()  << *** in may places
> > 
> > 
> > *** a printk() call from here will kill the system. either it will
> > recurse printk(), or spin forever in 'nested' printk() on one of
> > the already taken spin locks.
> 
> Exactly. Calling printk() from certain parts of the kernel (like scheduler
> code or timer code) has been always unsafe because printk itself uses these
> parts and so it can lead to deadlocks. That's why printk_deffered() has
> been introduced as you mention below.
> 
> And with sync printk the above deadlock doesn't trigger only by chance - if
> there happened to be a waiter on console_sem while we suspend, the same
> deadlock would trigger because up(&console_sem) will try to wake him up and
> the warning in timekeeping code will cause recursive printk.
> 
> So I think your patch doesn't really address the real issue - it only
> works around the particular WARN_ON(timekeeping_enabled) warning but if
> there was a different warning in timekeeping code which would trigger, it
> has a potential for causing recursive printk deadlock (and indeed we had
> such issues previously - see e.g. 504d58745c9c "timer: Fix lock inversion
> between hrtimer_bases.lock and scheduler locks").
> 
> So there are IMHO two issues here worth looking at:
> 
> 1) I didn't find how a wakeup would would lead to calling to ktime_get() in
> the current upstream kernel or even current RT kernel. Maybe this is a
> problem specific to the 3.10 kernel you are using? If yes, we don't have to
> do anything for current upstream AFAIU.
> 
> If I just missed how wakeup can call into ktime_get() in current upstream,
> there is another question:
> 
> 2) Is it OK that printk calls wakeup so late during suspend? I believe it
> is but I'm neither scheduler nor suspend expert.

I don't think it really is OK.  Nothing will wake up for sure at this point,
so why to do that in the first place?

> If it is OK, and wakeup can lead to ktime_get() in current upstream, then
> this contradicts the check WARN_ON(timekeeping_suspended) in ktime_get() and
> something is wrong.

Thanks,
Rafael

[toc] | [prev] | [next] | [standalone]

#1443488

On Thu 14-07-16 16:33:38, Rafael J. Wysocki wrote:
> On Thursday, July 14, 2016 04:12:16 PM Jan Kara wrote:
> > On Wed 13-07-16 14:45:07, Sergey Senozhatsky wrote:
> > > Cc Petr Mladek.
> > > 
> > > On (07/12/16 16:19), Viresh Kumar wrote:
> > > [..]
> > > > Okay, we have tracked this BUG and its really interesting.
> > > 
> > > good find!
> > > 
> > > > I hacked the platform's serial driver to implement a putchar() routine
> > > > that simply writes to the FIFO in polling mode, that helped us in
> > > > tracing on where we are going wrong.
> > > > 
> > > > The problem is that we are running asynchronous printks and we call
> > > > wake_up_process() from the last running CPU which has disabled
> > > > interrupts. That takes us to: try_to_wake_up().
> > > > 
> > > > In our case the CPU gets deadlocked on this line in try_to_wake_up().
> > > > 
> > > >         raw_spin_lock_irqsave(&p->pi_lock, flags);
> > > 
> > > yeah, printk() can't handle these types of recursion. it can prevent
> > > printk() calls issued from within the logbuf_lock spinlock section,
> > > with some limitations:
> > > 
> > > 	if (unlikely(logbuf_cpu == smp_processor_id())) {
> > > 		recursion_bug = true;
> > > 		return;
> > > 	}
> > > 
> > > 	raw_spin_lock(&logbuf_lock);
> > > 	logbuf_cpu = this_cpu;
> > > 		...
> > > 	logbuf_cpu = UINT_MAX;
> > > 	raw_spin_unlock(&logbuf_lock);
> > > 
> > > so should, for instance, raw_spin_unlock() generate spin_dump(), printk()
> > > will blow up (both sync and async), because logbuf_cpu is already reset.
> > > it may look that async printk added another source of recursion - wake_up().
> > > but, apparently, this is not exactly correct. because there is already a
> > > wake_up() call in console_unlock() - up().
> > > 
> > > 	printk()
> > > 	 if (logbuf_cpu == smp_processor_id())
> > > 		return;
> > > 
> > >          raw_spin_lock(&logbuf_lock);
> > > 	 logbuf_cpu = this_cpu;
> > > 	 ...
> > > 	 logbuf_cpu = UINT_MAX;
> > >          raw_spin_unlock(&logbuf_lock);
> > > 
> > > 	 console_trylock()
> > > 	   raw_spin_lock_irqsave(&sem->lock)      << ***
> > > 	   raw_spin_unlock_irqsave(&sem->lock)    << ***
> > > 
> > > 	 console_unlock()
> > >           up()
> > > 	   raw_spin_lock_irqsave(&sem->lock)  << ***
> > > 	    __up()
> > > 	     wake_up_process()
> > > 	      try_to_wake_up()  << *** in may places
> > > 
> > > 
> > > *** a printk() call from here will kill the system. either it will
> > > recurse printk(), or spin forever in 'nested' printk() on one of
> > > the already taken spin locks.
> > 
> > Exactly. Calling printk() from certain parts of the kernel (like scheduler
> > code or timer code) has been always unsafe because printk itself uses these
> > parts and so it can lead to deadlocks. That's why printk_deffered() has
> > been introduced as you mention below.
> > 
> > And with sync printk the above deadlock doesn't trigger only by chance - if
> > there happened to be a waiter on console_sem while we suspend, the same
> > deadlock would trigger because up(&console_sem) will try to wake him up and
> > the warning in timekeeping code will cause recursive printk.
> > 
> > So I think your patch doesn't really address the real issue - it only
> > works around the particular WARN_ON(timekeeping_enabled) warning but if
> > there was a different warning in timekeeping code which would trigger, it
> > has a potential for causing recursive printk deadlock (and indeed we had
> > such issues previously - see e.g. 504d58745c9c "timer: Fix lock inversion
> > between hrtimer_bases.lock and scheduler locks").
> > 
> > So there are IMHO two issues here worth looking at:
> > 
> > 1) I didn't find how a wakeup would would lead to calling to ktime_get() in
> > the current upstream kernel or even current RT kernel. Maybe this is a
> > problem specific to the 3.10 kernel you are using? If yes, we don't have to
> > do anything for current upstream AFAIU.
> > 
> > If I just missed how wakeup can call into ktime_get() in current upstream,
> > there is another question:
> > 
> > 2) Is it OK that printk calls wakeup so late during suspend? I believe it
> > is but I'm neither scheduler nor suspend expert.
> 
> I don't think it really is OK.  Nothing will wake up for sure at this point,
> so why to do that in the first place?

So that the process is put into a runnable state (currently it is in
uninterruptible sleep) and may run after the system resumes?

								Honza

-- 
Jan Kara <jack@suse.com>
SUSE Labs, CR

[toc] | [prev] | [next] | [standalone]

#1443491

On Thursday, July 14, 2016 04:39:39 PM Jan Kara wrote:
> On Thu 14-07-16 16:33:38, Rafael J. Wysocki wrote:
> > On Thursday, July 14, 2016 04:12:16 PM Jan Kara wrote:
> > > On Wed 13-07-16 14:45:07, Sergey Senozhatsky wrote:
> > > > Cc Petr Mladek.
> > > > 
> > > > On (07/12/16 16:19), Viresh Kumar wrote:
> > > > [..]
> > > > > Okay, we have tracked this BUG and its really interesting.
> > > > 
> > > > good find!
> > > > 
> > > > > I hacked the platform's serial driver to implement a putchar() routine
> > > > > that simply writes to the FIFO in polling mode, that helped us in
> > > > > tracing on where we are going wrong.
> > > > > 
> > > > > The problem is that we are running asynchronous printks and we call
> > > > > wake_up_process() from the last running CPU which has disabled
> > > > > interrupts. That takes us to: try_to_wake_up().
> > > > > 
> > > > > In our case the CPU gets deadlocked on this line in try_to_wake_up().
> > > > > 
> > > > >         raw_spin_lock_irqsave(&p->pi_lock, flags);
> > > > 
> > > > yeah, printk() can't handle these types of recursion. it can prevent
> > > > printk() calls issued from within the logbuf_lock spinlock section,
> > > > with some limitations:
> > > > 
> > > > 	if (unlikely(logbuf_cpu == smp_processor_id())) {
> > > > 		recursion_bug = true;
> > > > 		return;
> > > > 	}
> > > > 
> > > > 	raw_spin_lock(&logbuf_lock);
> > > > 	logbuf_cpu = this_cpu;
> > > > 		...
> > > > 	logbuf_cpu = UINT_MAX;
> > > > 	raw_spin_unlock(&logbuf_lock);
> > > > 
> > > > so should, for instance, raw_spin_unlock() generate spin_dump(), printk()
> > > > will blow up (both sync and async), because logbuf_cpu is already reset.
> > > > it may look that async printk added another source of recursion - wake_up().
> > > > but, apparently, this is not exactly correct. because there is already a
> > > > wake_up() call in console_unlock() - up().
> > > > 
> > > > 	printk()
> > > > 	 if (logbuf_cpu == smp_processor_id())
> > > > 		return;
> > > > 
> > > >          raw_spin_lock(&logbuf_lock);
> > > > 	 logbuf_cpu = this_cpu;
> > > > 	 ...
> > > > 	 logbuf_cpu = UINT_MAX;
> > > >          raw_spin_unlock(&logbuf_lock);
> > > > 
> > > > 	 console_trylock()
> > > > 	   raw_spin_lock_irqsave(&sem->lock)      << ***
> > > > 	   raw_spin_unlock_irqsave(&sem->lock)    << ***
> > > > 
> > > > 	 console_unlock()
> > > >           up()
> > > > 	   raw_spin_lock_irqsave(&sem->lock)  << ***
> > > > 	    __up()
> > > > 	     wake_up_process()
> > > > 	      try_to_wake_up()  << *** in may places
> > > > 
> > > > 
> > > > *** a printk() call from here will kill the system. either it will
> > > > recurse printk(), or spin forever in 'nested' printk() on one of
> > > > the already taken spin locks.
> > > 
> > > Exactly. Calling printk() from certain parts of the kernel (like scheduler
> > > code or timer code) has been always unsafe because printk itself uses these
> > > parts and so it can lead to deadlocks. That's why printk_deffered() has
> > > been introduced as you mention below.
> > > 
> > > And with sync printk the above deadlock doesn't trigger only by chance - if
> > > there happened to be a waiter on console_sem while we suspend, the same
> > > deadlock would trigger because up(&console_sem) will try to wake him up and
> > > the warning in timekeeping code will cause recursive printk.
> > > 
> > > So I think your patch doesn't really address the real issue - it only
> > > works around the particular WARN_ON(timekeeping_enabled) warning but if
> > > there was a different warning in timekeeping code which would trigger, it
> > > has a potential for causing recursive printk deadlock (and indeed we had
> > > such issues previously - see e.g. 504d58745c9c "timer: Fix lock inversion
> > > between hrtimer_bases.lock and scheduler locks").
> > > 
> > > So there are IMHO two issues here worth looking at:
> > > 
> > > 1) I didn't find how a wakeup would would lead to calling to ktime_get() in
> > > the current upstream kernel or even current RT kernel. Maybe this is a
> > > problem specific to the 3.10 kernel you are using? If yes, we don't have to
> > > do anything for current upstream AFAIU.
> > > 
> > > If I just missed how wakeup can call into ktime_get() in current upstream,
> > > there is another question:
> > > 
> > > 2) Is it OK that printk calls wakeup so late during suspend? I believe it
> > > is but I'm neither scheduler nor suspend expert.
> > 
> > I don't think it really is OK.  Nothing will wake up for sure at this point,
> > so why to do that in the first place?
> 
> So that the process is put into a runnable state (currently it is in
> uninterruptible sleep) and may run after the system resumes?

Fair enough.

But calling ktime_get() with suspended timekeeping is dumb at best which
is why the warning is there.

Thanks,
Rafael

[toc] | [prev] | [next] | [standalone]

#1443503

On Thu 14-07-16 16:47:11, Rafael J. Wysocki wrote:
> On Thursday, July 14, 2016 04:39:39 PM Jan Kara wrote:
> > On Thu 14-07-16 16:33:38, Rafael J. Wysocki wrote:
> > > On Thursday, July 14, 2016 04:12:16 PM Jan Kara wrote:
> > > > On Wed 13-07-16 14:45:07, Sergey Senozhatsky wrote:
> > > > > Cc Petr Mladek.
> > > > > 
> > > > > On (07/12/16 16:19), Viresh Kumar wrote:
> > > > > [..]
> > > > > > Okay, we have tracked this BUG and its really interesting.
> > > > > 
> > > > > good find!
> > > > > 
> > > > > > I hacked the platform's serial driver to implement a putchar() routine
> > > > > > that simply writes to the FIFO in polling mode, that helped us in
> > > > > > tracing on where we are going wrong.
> > > > > > 
> > > > > > The problem is that we are running asynchronous printks and we call
> > > > > > wake_up_process() from the last running CPU which has disabled
> > > > > > interrupts. That takes us to: try_to_wake_up().
> > > > > > 
> > > > > > In our case the CPU gets deadlocked on this line in try_to_wake_up().
> > > > > > 
> > > > > >         raw_spin_lock_irqsave(&p->pi_lock, flags);
> > > > > 
> > > > > yeah, printk() can't handle these types of recursion. it can prevent
> > > > > printk() calls issued from within the logbuf_lock spinlock section,
> > > > > with some limitations:
> > > > > 
> > > > > 	if (unlikely(logbuf_cpu == smp_processor_id())) {
> > > > > 		recursion_bug = true;
> > > > > 		return;
> > > > > 	}
> > > > > 
> > > > > 	raw_spin_lock(&logbuf_lock);
> > > > > 	logbuf_cpu = this_cpu;
> > > > > 		...
> > > > > 	logbuf_cpu = UINT_MAX;
> > > > > 	raw_spin_unlock(&logbuf_lock);
> > > > > 
> > > > > so should, for instance, raw_spin_unlock() generate spin_dump(), printk()
> > > > > will blow up (both sync and async), because logbuf_cpu is already reset.
> > > > > it may look that async printk added another source of recursion - wake_up().
> > > > > but, apparently, this is not exactly correct. because there is already a
> > > > > wake_up() call in console_unlock() - up().
> > > > > 
> > > > > 	printk()
> > > > > 	 if (logbuf_cpu == smp_processor_id())
> > > > > 		return;
> > > > > 
> > > > >          raw_spin_lock(&logbuf_lock);
> > > > > 	 logbuf_cpu = this_cpu;
> > > > > 	 ...
> > > > > 	 logbuf_cpu = UINT_MAX;
> > > > >          raw_spin_unlock(&logbuf_lock);
> > > > > 
> > > > > 	 console_trylock()
> > > > > 	   raw_spin_lock_irqsave(&sem->lock)      << ***
> > > > > 	   raw_spin_unlock_irqsave(&sem->lock)    << ***
> > > > > 
> > > > > 	 console_unlock()
> > > > >           up()
> > > > > 	   raw_spin_lock_irqsave(&sem->lock)  << ***
> > > > > 	    __up()
> > > > > 	     wake_up_process()
> > > > > 	      try_to_wake_up()  << *** in may places
> > > > > 
> > > > > 
> > > > > *** a printk() call from here will kill the system. either it will
> > > > > recurse printk(), or spin forever in 'nested' printk() on one of
> > > > > the already taken spin locks.
> > > > 
> > > > Exactly. Calling printk() from certain parts of the kernel (like scheduler
> > > > code or timer code) has been always unsafe because printk itself uses these
> > > > parts and so it can lead to deadlocks. That's why printk_deffered() has
> > > > been introduced as you mention below.
> > > > 
> > > > And with sync printk the above deadlock doesn't trigger only by chance - if
> > > > there happened to be a waiter on console_sem while we suspend, the same
> > > > deadlock would trigger because up(&console_sem) will try to wake him up and
> > > > the warning in timekeeping code will cause recursive printk.
> > > > 
> > > > So I think your patch doesn't really address the real issue - it only
> > > > works around the particular WARN_ON(timekeeping_enabled) warning but if
> > > > there was a different warning in timekeeping code which would trigger, it
> > > > has a potential for causing recursive printk deadlock (and indeed we had
> > > > such issues previously - see e.g. 504d58745c9c "timer: Fix lock inversion
> > > > between hrtimer_bases.lock and scheduler locks").
> > > > 
> > > > So there are IMHO two issues here worth looking at:
> > > > 
> > > > 1) I didn't find how a wakeup would would lead to calling to ktime_get() in
> > > > the current upstream kernel or even current RT kernel. Maybe this is a
> > > > problem specific to the 3.10 kernel you are using? If yes, we don't have to
> > > > do anything for current upstream AFAIU.
> > > > 
> > > > If I just missed how wakeup can call into ktime_get() in current upstream,
> > > > there is another question:
> > > > 
> > > > 2) Is it OK that printk calls wakeup so late during suspend? I believe it
> > > > is but I'm neither scheduler nor suspend expert.
> > > 
> > > I don't think it really is OK.  Nothing will wake up for sure at this point,
> > > so why to do that in the first place?
> > 
> > So that the process is put into a runnable state (currently it is in
> > uninterruptible sleep) and may run after the system resumes?
> 
> Fair enough.
> 
> But calling ktime_get() with suspended timekeeping is dumb at best which
> is why the warning is there.

Agree on that - but that seems to be a problem of a particular wakeup
implementation of the 3.10 kernel Viresh is using, not a problem of the
upstream kernel.

								Honza
-- 
Jan Kara <jack@suse.com>
SUSE Labs, CR

[toc] | [prev] | [next] | [standalone]

Page 2 of 3 — ← Prev page 1 [2] 3  Next page →

Back to top | Article view | linux.kernel

csiph-web