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