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

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

[Rafael J. Wysocki]

On Monday, July 11, 2016 03:46:01 PM Viresh Kumar wrote:
> On 12-07-16, 00:44, Rafael J. Wysocki wrote:
> > On Monday, July 11, 2016 03:35:01 PM Viresh Kumar wrote:
> > > Hi Sergey and Jan,
> > > 
> > > On 12-07-16, 00:44, Sergey Senozhatsky wrote:
> > > > right. apart from cases when the existing console_unlock() behaviour can
> > > > simply "block" a process to flush the log_buf to slow serial consoles
> > > > (regardless the  process execution context) and make the system less
> > > > responsive, I have around ~10 absolutely different scenarios on my list that
> > > > may cause soft/hard lockups, rcu stalls, oom-s, etc. and console_unlock() is
> > > > the root cause there. the simplest ones involve heavy printk() usage, the
> > > > trickier ones do not necessarily have anything that is abusing printk(): a
> > > > moderate printk() pressure coming from other CPUs on the system and more or
> > > > less active tty -> UART can do the trick, because uart interrupt service
> > > > routine and call_console_drivers()->write() have to compete for the same
> > > > uart port spin_lock. soft lockups are probably the most common problems,
> > > > though, it's not all that easy to catch, because watchdog does not ring
> > > > the bell straight after preempt_enable(), but from hrtimer interrupt, that
> > > > happens approx every 4 seconds. by this time CPU can be somewhere far away
> > > > from console_unlock(). I had an idea of doing watchdog soft lockup check
> > > > from preempt_enable(), when it brings preempt_count down to zero, but not
> > > > sure I can recall how well did it go.
> > > 
> > > Thanks for your feedback guys, and I have one more blocking issue
> > > where I need your help/advice.
> > > 
> > > So, the excess printing in our case is done in parallel to system
> > > suspend. And that can very much happen after all the non-boot CPUs are
> > > offlined.
> > > 
> > > 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.
> > 
> > But no_console_suspend is best-effort by design.
> 
> Yeah and I am not sure how should I go ahead about this issue now :)

FWIW, I think the reason why the "synchronous printk" works is because after
disabling the non-boot CPU, the only remaining one disables local interrupts
and won't do any async work any more until resume.

> > And *please* CC PM-related stuff to linux-pm.
> 
> Sure. I wasn't sure initially when this thread got started, that it is
> a PM related stuff and so didn't do it. As it was all about printk and
> hogging :)

But you started to talk about suspend/resume and such at one point and that
message should have been CCed to linux-pm.

And the reason why is because problems you see during suspend/resume may very
well be suspend-specific and not visible otherwise.  In which case you'll
likely need input from the people on linux-pm.

Thanks,
Rafael

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

[Viresh Kumar]

On 12-07-16, 14:24, Rafael J. Wysocki wrote:
> On Monday, July 11, 2016 03:46:01 PM Viresh Kumar wrote:
> > Yeah and I am not sure how should I go ahead about this issue now :)
> 
> FWIW, I think the reason why the "synchronous printk" works is because after
> disabling the non-boot CPU, the only remaining one disables local interrupts
> and won't do any async work any more until resume.

Right. After disabling interrupts, the other printk messages gets
printed only after the system resumes. I am not that worried about
printk not working after that point, but on how does asynchronous
printing affect the system to crash or come to a complete hang?

Any clues on why that can happen ?

> But you started to talk about suspend/resume and such at one point and that
> message should have been CCed to linux-pm.
> 
> And the reason why is because problems you see during suspend/resume may very
> well be suspend-specific and not visible otherwise.  In which case you'll
> likely need input from the people on linux-pm.

Yeah, I *should* have cc'd the PM list then. Thanks for helping out
Rafael :)

-- 
viresh

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

[Viresh Kumar]

+Rafael and linux-pm to this thread :)

On 12-07-16, 14:52, Petr Mladek wrote:
> On Tue 2016-07-12 18:38:05, Sergey Senozhatsky wrote:
> > Hello,
> > 
> > On (07/11/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
> 
> I guess that the printk() kthread is not longer scheduled when there
> is only one CPU left.

Yeah, so I tried debugging this more and I am able to get printing
done to just before arch_suspend_disable_irqs() in suspend.c and then
it stops because of the async nature.

I get to this point for both successful suspend/resume (where system
resumes back successfully) and in the bad case (where the system just
hangs/crashes).

FWIW, I also tried commenting out following in suspend_enter():

        error = suspend_ops->enter(state);

so that the system doesn't go into suspend at all, and just resume
back immediately (similar to TEST_CORE) and I saw the hang/crash then
as well one of the times.

> We might try to explicitly flush the consoles in suspend_console().

That wouldn't happen as I have disabled console-suspend.

> But I am not sure if we always want to do so because it might take
> a while. Also it need not help if someone already owns the
> console_sem. Note the console_unlock() calls the cond_resched()
> when in safe context.
> 
> Well, we might do the best effort when no_console_suspend is enabled.

Hmm.. I have no reasoning yet on why the system comes to a complete
stop and a forceful reboot only makes it work :(

-- 
viresh

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

[Petr Mladek]

On Tue 2016-07-12 06:02:31, Viresh Kumar wrote:
> On 12-07-16, 14:24, Rafael J. Wysocki wrote:
> > On Monday, July 11, 2016 03:46:01 PM Viresh Kumar wrote:
> > > Yeah and I am not sure how should I go ahead about this issue now :)
> > 
> > FWIW, I think the reason why the "synchronous printk" works is because after
> > disabling the non-boot CPU, the only remaining one disables local interrupts
> > and won't do any async work any more until resume.
> 
> Right. After disabling interrupts, the other printk messages gets
> printed only after the system resumes. I am not that worried about
> printk not working after that point, but on how does asynchronous
> printing affect the system to crash or come to a complete hang?

Ah, I have missed that the hang happens only when you use the async
printk patchset.

I wonder if it is somehow related to the commit 8d91f8b15361dfb438ab
("printk: do cond_resched() between lines while outputting to
consoles"). A process (printk thread) might sleep with taken
console_sem. Then suspend_console() might be unable to
get the semaphore in console_lock() and might deadlock.

Does it help to enable "no_console_suspend" please?


Best Regards,
Petr

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

[Viresh Kumar]

On 12-07-16, 15:56, Petr Mladek wrote:
> Ah, I have missed that the hang happens only when you use the async
> printk patchset.

And that also doesn't happen always, but only sometimes. So there is a
race somewhere I feel :)

> I wonder if it is somehow related to the commit 8d91f8b15361dfb438ab
> ("printk: do cond_resched() between lines while outputting to
> consoles"). A process (printk thread) might sleep with taken
> console_sem. Then suspend_console() might be unable to
> get the semaphore in console_lock() and might deadlock.

I am not sure at this point really, and I don't have indepth knowledge
of printk core as well (I should accept that here :).

> Does it help to enable "no_console_suspend" please?

No. With no_console_suspend, we just print one more line (Disabling
non-boot CPUs) and once the interrupt on the local CPU are disabled,
we don't get any more prints until a resume happens.

-- 
viresh

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

[Viresh Kumar]

On 12-07-16, 06:12, Viresh Kumar wrote:

> Yeah, so I tried debugging this more and I am able to get printing
> done to just before arch_suspend_disable_irqs() in suspend.c and then
> it stops because of the async nature.
> 
> I get to this point for both successful suspend/resume (where system
> resumes back successfully) and in the bad case (where the system just
> hangs/crashes).
> 
> FWIW, I also tried commenting out following in suspend_enter():
> 
>         error = suspend_ops->enter(state);
> 
> so that the system doesn't go into suspend at all, and just resume
> back immediately (similar to TEST_CORE) and I saw the hang/crash then
> as well one of the times.

So I tried it cleanly without any local hacks using:

echo core > /sys/power/pm_test

and I still see the problem, so whatever happens, happens before
putting the system into complete suspend.

FWIW, I also tried this hacky thing:

diff --git a/kernel/power/suspend.c b/kernel/power/suspend.c
index bc71478fac26..045ebc88fe08 100644
--- a/kernel/power/suspend.c
+++ b/kernel/power/suspend.c
@@ -170,6 +170,7 @@ void __attribute__ ((weak)) arch_suspend_enable_irqs(void)
  *
  * This function should be called after devices have been suspended.
  */
+extern bool printk_sync_suspended;
 static int suspend_enter(suspend_state_t state, bool *wakeup)
 {
        char suspend_abort[MAX_SUSPEND_ABORT_LEN];
@@ -218,6 +219,7 @@ static int suspend_enter(suspend_state_t state, bool *wakeup)
        }
 
        arch_suspend_disable_irqs();
+       printk_sync_suspended = true;
        BUG_ON(!irqs_disabled());
 
        error = syscore_suspend();
@@ -237,6 +239,7 @@ static int suspend_enter(suspend_state_t state, bool *wakeup)
                syscore_resume();
        }
 
+       printk_sync_suspended = false;
        arch_suspend_enable_irqs();
        BUG_ON(irqs_disabled());
 
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 46bb017ac2c9..187054074b96 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -293,6 +293,7 @@ static u32 log_buf_len = __LOG_BUF_LEN;
 
 /* Control whether printing to console must be synchronous. */
 static bool __read_mostly printk_sync = false;
+bool printk_sync_suspended = false;
 /* Printing kthread for async printk */
 static struct task_struct *printk_kthread;
 /* When `true' printing thread has messages to print */
@@ -300,7 +301,7 @@ static bool printk_kthread_need_flush_console;
 
 static inline bool can_printk_async(void)
 {
-       return !printk_sync && printk_kthread;
+       return !printk_sync && !printk_sync_suspended && printk_kthread;
 }
 
 /* Return log buffer address */


i.e. I disabled async-printk after interrupts are disabled on the last
running CPU (0) and enabled it again before enabling interrupts back.

This FIXES the hangs for me :)


I don't think its a crash but some sort of deadlock in async printk
thread because of the state it was left in before we offlined all
other CPUs and disabled interrupts on the local one.

-- 
viresh

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

[Rafael J. Wysocki]

On Tue, Jul 12, 2016 at 7:11 PM, Viresh Kumar <viresh.kumar@linaro.org> wrote:
> On 12-07-16, 06:12, Viresh Kumar wrote:
>
>> Yeah, so I tried debugging this more and I am able to get printing
>> done to just before arch_suspend_disable_irqs() in suspend.c and then
>> it stops because of the async nature.
>>
>> I get to this point for both successful suspend/resume (where system
>> resumes back successfully) and in the bad case (where the system just
>> hangs/crashes).
>>
>> FWIW, I also tried commenting out following in suspend_enter():
>>
>>         error = suspend_ops->enter(state);
>>
>> so that the system doesn't go into suspend at all, and just resume
>> back immediately (similar to TEST_CORE) and I saw the hang/crash then
>> as well one of the times.
>
> So I tried it cleanly without any local hacks using:
>
> echo core > /sys/power/pm_test
>
> and I still see the problem, so whatever happens, happens before
> putting the system into complete suspend.
>
> FWIW, I also tried this hacky thing:
>
> diff --git a/kernel/power/suspend.c b/kernel/power/suspend.c
> index bc71478fac26..045ebc88fe08 100644
> --- a/kernel/power/suspend.c
> +++ b/kernel/power/suspend.c
> @@ -170,6 +170,7 @@ void __attribute__ ((weak)) arch_suspend_enable_irqs(void)
>   *
>   * This function should be called after devices have been suspended.
>   */
> +extern bool printk_sync_suspended;
>  static int suspend_enter(suspend_state_t state, bool *wakeup)
>  {
>         char suspend_abort[MAX_SUSPEND_ABORT_LEN];
> @@ -218,6 +219,7 @@ static int suspend_enter(suspend_state_t state, bool *wakeup)
>         }
>
>         arch_suspend_disable_irqs();
> +       printk_sync_suspended = true;
>         BUG_ON(!irqs_disabled());
>
>         error = syscore_suspend();
> @@ -237,6 +239,7 @@ static int suspend_enter(suspend_state_t state, bool *wakeup)
>                 syscore_resume();
>         }
>
> +       printk_sync_suspended = false;
>         arch_suspend_enable_irqs();
>         BUG_ON(irqs_disabled());
>
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 46bb017ac2c9..187054074b96 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -293,6 +293,7 @@ static u32 log_buf_len = __LOG_BUF_LEN;
>
>  /* Control whether printing to console must be synchronous. */
>  static bool __read_mostly printk_sync = false;
> +bool printk_sync_suspended = false;
>  /* Printing kthread for async printk */
>  static struct task_struct *printk_kthread;
>  /* When `true' printing thread has messages to print */
> @@ -300,7 +301,7 @@ static bool printk_kthread_need_flush_console;
>
>  static inline bool can_printk_async(void)
>  {
> -       return !printk_sync && printk_kthread;
> +       return !printk_sync && !printk_sync_suspended && printk_kthread;
>  }
>
>  /* Return log buffer address */
>
>
> i.e. I disabled async-printk after interrupts are disabled on the last
> running CPU (0) and enabled it again before enabling interrupts back.
>
> This FIXES the hangs for me :)
>
> I don't think its a crash but some sort of deadlock in async printk
> thread because of the state it was left in before we offlined all
> other CPUs and disabled interrupts on the local one.

It looks like a new printk() waits for a previous one to make progress
and since progress cannot be made under the suspend conditions, it
waits forever.

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

[Viresh Kumar]

On 12-07-16, 21:59, Rafael J. Wysocki wrote:
> It looks like a new printk() waits for a previous one to make progress
> and since progress cannot be made under the suspend conditions, it
> waits forever.

Thanks.

Maybe, but to mention this clearly again, this doesn't happen
every time. Sometime it takes 100 suspend/resume cycles to hit this
thing.

Lets see what Jan and Sergey have to say on this, as they were the
ones who wrote these patches :)

-- 
viresh

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

[Viresh Kumar]

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

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

[Viresh Kumar]

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

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

[Sergey Senozhatsky]

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

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

[Sergey Senozhatsky]

On (07/12/16 10:11), Viresh Kumar wrote:
> +extern bool printk_sync_suspended;
>  static int suspend_enter(suspend_state_t state, bool *wakeup)
>  {
>         char suspend_abort[MAX_SUSPEND_ABORT_LEN];
> @@ -218,6 +219,7 @@ static int suspend_enter(suspend_state_t state, bool *wakeup)
>         }
>  
>         arch_suspend_disable_irqs();
> +       printk_sync_suspended = true;
>         BUG_ON(!irqs_disabled());
>  
>         error = syscore_suspend();
> @@ -237,6 +239,7 @@ static int suspend_enter(suspend_state_t state, bool *wakeup)
>                 syscore_resume();
>         }
>  
> +       printk_sync_suspended = false;
>         arch_suspend_enable_irqs();
>         BUG_ON(irqs_disabled());
>  
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 46bb017ac2c9..187054074b96 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -293,6 +293,7 @@ static u32 log_buf_len = __LOG_BUF_LEN;
>  
>  /* Control whether printing to console must be synchronous. */
>  static bool __read_mostly printk_sync = false;
> +bool printk_sync_suspended = false;
>  /* Printing kthread for async printk */
>  static struct task_struct *printk_kthread;
>  /* When `true' printing thread has messages to print */
> @@ -300,7 +301,7 @@ static bool printk_kthread_need_flush_console;
>  
>  static inline bool can_printk_async(void)
>  {
> -       return !printk_sync && printk_kthread;
> +       return !printk_sync && !printk_sync_suspended && printk_kthread;
>  }
>  
>  /* Return log buffer address */
> 
> 
> i.e. I disabled async-printk after interrupts are disabled on the last
> running CPU (0) and enabled it again before enabling interrupts back.
> 
> This FIXES the hangs for me :)

ah, just saw this. OK, very close to what I sent in another thread, so I
guess it will work on your side.
let me know if it doesn't, I'll fold it into 0001 and re-spin the series.
thanks for your help!


I'll also drop the KERN_CONT patch for now. apparently it didn't work for
Petr.

	-ss

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

[Rafael J. Wysocki]

On Wed, Jul 13, 2016 at 9:00 AM, Sergey Senozhatsky
<sergey.senozhatsky.work@gmail.com> wrote:
> On (07/12/16 10:11), Viresh Kumar wrote:
>> +extern bool printk_sync_suspended;
>>  static int suspend_enter(suspend_state_t state, bool *wakeup)
>>  {
>>         char suspend_abort[MAX_SUSPEND_ABORT_LEN];
>> @@ -218,6 +219,7 @@ static int suspend_enter(suspend_state_t state, bool *wakeup)
>>         }
>>
>>         arch_suspend_disable_irqs();
>> +       printk_sync_suspended = true;
>>         BUG_ON(!irqs_disabled());
>>
>>         error = syscore_suspend();
>> @@ -237,6 +239,7 @@ static int suspend_enter(suspend_state_t state, bool *wakeup)
>>                 syscore_resume();
>>         }
>>
>> +       printk_sync_suspended = false;
>>         arch_suspend_enable_irqs();
>>         BUG_ON(irqs_disabled());
>>
>> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
>> index 46bb017ac2c9..187054074b96 100644
>> --- a/kernel/printk/printk.c
>> +++ b/kernel/printk/printk.c
>> @@ -293,6 +293,7 @@ static u32 log_buf_len = __LOG_BUF_LEN;
>>
>>  /* Control whether printing to console must be synchronous. */
>>  static bool __read_mostly printk_sync = false;
>> +bool printk_sync_suspended = false;
>>  /* Printing kthread for async printk */
>>  static struct task_struct *printk_kthread;
>>  /* When `true' printing thread has messages to print */
>> @@ -300,7 +301,7 @@ static bool printk_kthread_need_flush_console;
>>
>>  static inline bool can_printk_async(void)
>>  {
>> -       return !printk_sync && printk_kthread;
>> +       return !printk_sync && !printk_sync_suspended && printk_kthread;
>>  }
>>
>>  /* Return log buffer address */
>>
>>
>> i.e. I disabled async-printk after interrupts are disabled on the last
>> running CPU (0) and enabled it again before enabling interrupts back.
>>
>> This FIXES the hangs for me :)
>
> ah, just saw this. OK, very close to what I sent in another thread, so I
> guess it will work on your side.
> let me know if it doesn't, I'll fold it into 0001 and re-spin the series.
> thanks for your help!

But you need to do an analogous thing for hibernation.  Essentially,
wherever disable_nonboot_cpus() is called.

Thanks,
Rafael

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

[Sergey Senozhatsky]

Hello Rafael,

On (07/13/16 14:05), Rafael J. Wysocki wrote:
[..]
> > ah, just saw this. OK, very close to what I sent in another thread, so I
> > guess it will work on your side.
> > let me know if it doesn't, I'll fold it into 0001 and re-spin the series.
> > thanks for your help!
> 
> But you need to do an analogous thing for hibernation.  Essentially,
> wherever disable_nonboot_cpus() is called.

hibernation() suspends console, and suspend_console() forces printk to
switch to sync mode. resume_console() lets printk to operate in async
mode (if printk was configured to operate in async mode at all).

the patch I'm talking about is:
 http://marc.info/?l=linux-kernel&m=146838876027364&w=2

am I missing something?

	-ss

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

[Rafael J. Wysocki]

On Wed, Jul 13, 2016 at 2:57 PM, Sergey Senozhatsky
<sergey.senozhatsky@gmail.com> wrote:
> Hello Rafael,
>
> On (07/13/16 14:05), Rafael J. Wysocki wrote:
> [..]
>> > ah, just saw this. OK, very close to what I sent in another thread, so I
>> > guess it will work on your side.
>> > let me know if it doesn't, I'll fold it into 0001 and re-spin the series.
>> > thanks for your help!
>>
>> But you need to do an analogous thing for hibernation.  Essentially,
>> wherever disable_nonboot_cpus() is called.
>
> hibernation() suspends console, and suspend_console() forces printk to
> switch to sync mode. resume_console() lets printk to operate in async
> mode (if printk was configured to operate in async mode at all).
>
> the patch I'm talking about is:
>  http://marc.info/?l=linux-kernel&m=146838876027364&w=2

Ah OK.  That should work for hibernation too.

> am I missing something?

No, I got confused for some reason.

Thanks,
Rafael

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

[Viresh Kumar]

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

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

[Rafael J. Wysocki]

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

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

[Viresh Kumar]

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

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

[Greg Kroah-Hartman]

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

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

[Sergey Senozhatsky]

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

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

[Rafael J. Wysocki]

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?

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

[Sergey Senozhatsky]

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

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

[Jan Kara]

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

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

[Rafael J. Wysocki]

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

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

[Sergey Senozhatsky]

Hello Jan,

On (07/14/16 16:12), Jan Kara wrote:
[..]
> > *** 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.
[..]
> 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").

we switch to sync printk in suspend_console(), that is happening
long before we start bringing cpu downs

suspend_devices_and_enter()
	suspend_console()
	...
	suspend_enter()
		...
		dpm_suspend_late
		...
		disable_nonboot_cpus



and cpu_down() in printk does

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;
}

so I think this console_lock() sort of guarantees that there should be
no sleeping tasks in console semaphore wait list. or am I missing something?

> 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.

I personally suspect it's an in-hose (custom) code.

	-ss

> 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
> 

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

[Jan Kara]

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

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

[Rafael J. Wysocki]

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

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

[Jan Kara]

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

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

[Jan Kara]

On Thu 14-07-16 23:34:50, Sergey Senozhatsky wrote:
> Hello Jan,
> 
> On (07/14/16 16:12), Jan Kara wrote:
> [..]
> > > *** 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.
> [..]
> > 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").
> 
> we switch to sync printk in suspend_console(), that is happening
> long before we start bringing cpu downs
> 
> suspend_devices_and_enter()
> 	suspend_console()
> 	...
> 	suspend_enter()
> 		...
> 		dpm_suspend_late
> 		...
> 		disable_nonboot_cpus
> 
> 
> 
> and cpu_down() in printk does
> 
> 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;
> }
> 
> so I think this console_lock() sort of guarantees that there should be
> no sleeping tasks in console semaphore wait list. or am I missing something?

No, probably you're right - unless there would be a CPU notifier executed
after console_cpu_notify() which would try to acquire console_sem for some
reason. But that is a wild speculation and I tend to agree that in
synchronous printk case and current code the wakeup cannot happen.

But my point really is that I don't see why changing process state (which
is what wakeup actually is) should be problematic even this late during
suspend...

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

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

[Viresh Kumar]

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

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

[Viresh Kumar]

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

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

[Viresh Kumar]

On 14-07-16, 16:12, Jan Kara wrote:
> 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.

I haven't checked that earlier, but I see the path in both 3.10 and mainline.

vprintk_emit
 -> wake_up_process
  -> try_to_wake_up
   -> ttwu_queue
    -> ttwu_do_activate
     -> ttwu_activate
      -> activate_task
       -> enqueue_task (sched/core.c)
        -> enqueue_task_rt (rt.c)
         -> enqueue_rt_entity
          -> __enqueue_rt_entity
           -> inc_rt_tasks
            -> inc_rt_group
             -> start_rt_bandwidth
              -> start_bandwidth_timer
               -> __hrtimer_start_range_ns
                -> ktime_get()

> 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?

To clarify again to everybody, we are talking about the place where all non-boot
CPUs are already hot-unplugged and the last running one has disabled interrupts.

I believe that we can't do migration at all now, right? What will we get by
calling wake_up_process() now anyway ?

> 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...

Thanks.

-- 
viresh

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

[Viresh Kumar]

On 14-07-16, 16:55, Jan Kara wrote:
> 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.

I think we can get it to trigger on mainline as well. Also to mention that I
also don't see it on every suspend. Probably hrtimer_active() call returns true
in the sequence somewhere earlier, and we don't have to go activate a hrtimer.

-- 
viresh

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

[Jan Kara]

On Thu 14-07-16 15:12:51, Viresh Kumar wrote:
> On 14-07-16, 16:12, Jan Kara wrote:
> > 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.
> 
> I haven't checked that earlier, but I see the path in both 3.10 and mainline.
> 
> vprintk_emit
>  -> wake_up_process
>   -> try_to_wake_up
>    -> ttwu_queue
>     -> ttwu_do_activate
>      -> ttwu_activate
>       -> activate_task
>        -> enqueue_task (sched/core.c)
>         -> enqueue_task_rt (rt.c)
>          -> enqueue_rt_entity
>           -> __enqueue_rt_entity
>            -> inc_rt_tasks
>             -> inc_rt_group
>              -> start_rt_bandwidth
>               -> start_bandwidth_timer
>                -> __hrtimer_start_range_ns
>                 -> ktime_get()

Yeah, you are right.

> > 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?
> 
> To clarify again to everybody, we are talking about the place where all
> non-boot CPUs are already hot-unplugged and the last running one has
> disabled interrupts.
> 
> I believe that we can't do migration at all now, right? What will we get by
> calling wake_up_process() now anyway ?

As I already wrote to Rafael, wake_up_process() will change the process
state to TASK_RUNNING so that it can run after we resume from suspend.

But seeing that the same problem is in upstream I guess what Sergey did
makes more sense if it works for you. If Sergey's fix does not work for you
due to too many messages being printed during device suspend, then we will
have to try something else...

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

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

[Rafael J. Wysocki]

On Monday, July 18, 2016 01:01:34 PM Jan Kara wrote:
> On Thu 14-07-16 15:12:51, Viresh Kumar wrote:
> > On 14-07-16, 16:12, Jan Kara wrote:
> > > 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.
> > 
> > I haven't checked that earlier, but I see the path in both 3.10 and mainline.
> > 
> > vprintk_emit
> >  -> wake_up_process
> >   -> try_to_wake_up
> >    -> ttwu_queue
> >     -> ttwu_do_activate
> >      -> ttwu_activate
> >       -> activate_task
> >        -> enqueue_task (sched/core.c)
> >         -> enqueue_task_rt (rt.c)
> >          -> enqueue_rt_entity
> >           -> __enqueue_rt_entity
> >            -> inc_rt_tasks
> >             -> inc_rt_group
> >              -> start_rt_bandwidth
> >               -> start_bandwidth_timer
> >                -> __hrtimer_start_range_ns
> >                 -> ktime_get()
> 
> Yeah, you are right.
> 
> > > 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?
> > 
> > To clarify again to everybody, we are talking about the place where all
> > non-boot CPUs are already hot-unplugged and the last running one has
> > disabled interrupts.
> > 
> > I believe that we can't do migration at all now, right? What will we get by
> > calling wake_up_process() now anyway ?
> 
> As I already wrote to Rafael, wake_up_process() will change the process
> state to TASK_RUNNING so that it can run after we resume from suspend.
> 
> But seeing that the same problem is in upstream I guess what Sergey did
> makes more sense if it works for you. If Sergey's fix does not work for you
> due to too many messages being printed during device suspend, then we will
> have to try something else...

Which is exactly my point. :-)

Thanks,
Rafael

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

[Viresh Kumar]

On 13-07-16, 14:45, Sergey Senozhatsky wrote:
> 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();

I haven't seen any issues with it yet and it works just fine. Please feel free
to add below for the entire series including this hunk.

Tested-by: Viresh Kumar <viresh.kumar@linaro.org>

-- 
viresh

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

[Sergey Senozhatsky]

On (07/29/16 13:42), Viresh Kumar wrote:
[..]
> I haven't seen any issues with it yet and it works just fine. Please feel free
> to add below for the entire series including this hunk.
> 
> Tested-by: Viresh Kumar <viresh.kumar@linaro.org>

Thanks a lot!
will refresh the series next week.

sorry, haven't gotten many chances to investigate the sched
throttling so far.

	-ss