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

Groups > linux.kernel > #1440446 > unrolled thread

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

Back to article view | Back to linux.kernel

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

Contents

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

Page 1 of 3  [1] 2 3  Next page →

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

On Wed 06-07-16 11:28:42, Viresh Kumar wrote:
> On 01-07-16, 12:22, Tejun Heo wrote:
> I enabled traces with '-e all' to look at everything happening on the
> CPU.
> 
> Following is what starts in the middle of the delayed-work handler:
> 
>     kworker/0:1H-40    [000] d..1  2994.918766: console: [ 2994.918754] ***
>     kworker/0:1H-40    [000] d..1  2994.923057: console: [ 2994.918817] ***
>     kworker/0:1H-40    [000] d..1  2994.935639: console: [ 2994.918842] ***
> 
> ... (more messages)
> 
>     kworker/0:1H-40    [000] d..1  2996.264372: console: [ 2994.943074] ***
>     kworker/0:1H-40    [000] d..1  2996.268622: console: [ 2994.943410] ***
>     kworker/0:1H-40    [000] d..1  2996.275050: ipi_entry: (Rescheduling interrupts)
> 
> 
> (*** are some specific errors to our usecase and aren't relevant here)
> 
> These print messages continue from 2994.918 to 2996.268 (1.35 seconds)
> and they hog the work-handler for that long, which results in watchdog
> reboot in our setup. The 3.10 kernel implementation of the printk
> looks like this (if I am not wrong):
> 
>         local_irq_save();
>         flush-console-buffer(); //console_unlock()
>         local_irq_restore();
> 
> So, the current CPU will try to print all the messages from the
> buffer, before enabling the interrupts again on the local CPU and so I
> don't see the hrtimer fire at all for almost a second.
> 
> 
> I tried looking at if something related to this changed between 3.10
> and mainline, and found few patches at least. One of the important
> ones is:
> 
> commit 5874af2003b1 ("printk: enable interrupts before calling
> console_trylock_for_printk()")
> 
> I wasn't able to backport it cleanly to 3.10 yet to see it makes thing
> work better though. But it looks like it was targeting similar
> problems.
> 
> @Jan Kara, Right ?

Yes. We have similar problems as you observe on machines when they do a lot
of printing (usually due to device discovery or similar reasons). The
problem is not fully solved even upstream as Andrew is reluctant to merge
the patches. Sergey (added to CC) has the latest version of the series [1].
If you are interested, I can send you the patches for 3.12 kernel which we
carry in SLES kernels and which fixes the issue for us. It is significanly
different from current upstream version but it works good enough for us.

								Honza

[1] https://lkml.org/lkml/2016/5/13/275
-- 
Jan Kara <jack@suse.com>
SUSE Labs, CR

[toc] | [next] | [standalone]

#1440723

Hello,

Thanks for Cc-ing.

I'm attending an internal 2-days training now, so I'm a bit
slow at answering emails, sorry.

On (07/11/16 12:26), Jan Kara wrote:
[..]
> > These print messages continue from 2994.918 to 2996.268 (1.35 seconds)
> > and they hog the work-handler for that long, which results in watchdog
> > reboot in our setup. The 3.10 kernel implementation of the printk
> > looks like this (if I am not wrong):
> > 
> >         local_irq_save();
> >         flush-console-buffer(); //console_unlock()
> >         local_irq_restore();
> > 
> > So, the current CPU will try to print all the messages from the
> > buffer, before enabling the interrupts again on the local CPU and so I
> > don't see the hrtimer fire at all for almost a second.
> > 

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.

> > I tried looking at if something related to this changed between 3.10
> > and mainline, and found few patches at least. One of the important
> > ones is:
> > 
> > commit 5874af2003b1 ("printk: enable interrupts before calling
> > console_trylock_for_printk()")
> > 
> > I wasn't able to backport it cleanly to 3.10 yet to see it makes thing
> > work better though. But it looks like it was targeting similar
> > problems.
> Yes. We have similar problems as you observe on machines when they do a lot
> of printing (usually due to device discovery or similar reasons). The
> problem is not fully solved even upstream as Andrew is reluctant to merge
> the patches. Sergey (added to CC) has the latest version of the series [1].
> If you are interested, I can send you the patches for 3.12 kernel which we
> carry in SLES kernels and which fixes the issue for us. It is significanly
> different from current upstream version but it works good enough for us.

yes, an alternative link /* lkml.org is pretty unreliable sometimes*/
is: http://marc.info/?l=linux-kernel&m=146314209118602

I don't have a backport to 3.10, sorry. I had it some time ago (not the
current version, tho), but I think I lost it by now, don't have to deal
with 3.10 anymore.

I'll re-spin the series in a day or two, I think. A rebased version
(against next-20160711), basically, has only that KERN_CONT patch as
part of 0001 now: http://marc.info/?l=linux-kernel&m=146717692431893

hopefully it will re-fresh the discussion and I'll be able to polish
the series so Andrew will be less sceptical about the whole thing.

	-ss

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

#1440948

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.

And *please* CC PM-related stuff to linux-pm.

Thanks,
Rafael

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

#1440955

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

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

-- 
viresh

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

#1441307

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

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

#1441337

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

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

#1441369

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

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

#1441376

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

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

#1440949

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.

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.

-- 
viresh

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

#1441181

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

hm... I'll take a look.

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

	-ss

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

#1441322

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.

> > 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.
> 
> hm... I'll take a look.

We might try to explicitly flush the consoles in suspend_console().
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.


Best Regards,
Petr

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

#1441343

+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

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

#1441602

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

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

#1441697

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

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

#1441702

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.

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

#1442051

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

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

#1442381

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

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

#1442425

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

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

#1442451

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

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

#1441384

Hello,

On (07/12/16 14:52), Petr Mladek wrote:
[..]
> > 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.
> 
> > > 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.
> > 
> > hm... I'll take a look.
> 
> We might try to explicitly flush the consoles in suspend_console().
> 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.

Thanks, Petr.


so, I'm looking at this thing now:

: [   12.874909] sched: RT throttling activated for rt_rq ffffffc0ac13fcd0 (cpu 0)
: [   12.874909] potential CPU hogs:
: [   12.874909]  printk (292)

so it's either cond_resched() does not reshed, keeping printk kthread
active, which, however, upsets the sched and triggers throttling (umm, what);

or we, somehow, have `console_may_schedule == 0' in this final console_unlock(),
so cond_resched() never happens.

I'm looking at mainline 3.10, tho.

Viresh, can you verify if we can do cond_resched() from console_unlock()
(console_may_schedule != 0) ?

	-ss

> Well, we might do the best effort when no_console_suspend is enabled.
> 
> 
> Best Regards,
> Petr
> 

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

Page 1 of 3  [1] 2 3  Next page →

Back to top | Article view | linux.kernel

csiph-web