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


Groups > linux.kernel > #1435502 > unrolled thread

[Query] Preemption (hogging) of the work handler

Started byViresh Kumar <viresh.kumar@linaro.org>
First post2016-07-01 19:10 +0200
Last post2016-07-11 21:10 +0200
Articles 20 on this page of 53 — 10 participants

Back to article view | Back to linux.kernel


Contents

  [Query] Preemption (hogging) of the work handler Viresh Kumar <viresh.kumar@linaro.org> - 2016-07-01 19:10 +0200
    Re: [Query] Preemption (hogging) of the work handler Tejun Heo <tj@kernel.org> - 2016-07-01 19:30 +0200
      Re: [Query] Preemption (hogging) of the work handler Viresh Kumar <viresh.kumar@linaro.org> - 2016-07-01 19:40 +0200
      Re: [Query] Preemption (hogging) of the work handler Viresh Kumar <viresh.kumar@linaro.org> - 2016-07-06 20:30 +0200
        Re: [Query] Preemption (hogging) of the work handler Viresh Kumar <viresh.kumar@linaro.org> - 2016-07-06 21:30 +0200
        Re: [Query] Preemption (hogging) of the work handler Steven Rostedt <rostedt@goodmis.org> - 2016-07-06 21:30 +0200
        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 →


#1435502 — [Query] Preemption (hogging) of the work handler

FromViresh Kumar <viresh.kumar@linaro.org>
Date2016-07-01 19:10 +0200
Subject[Query] Preemption (hogging) of the work handler
Message-ID<rQa70-Tn-35@gated-at.bofh.it>
Hi Tejun,

we are stuck with a typical issue on our octa-core ARM platform and
wanted to make sure that we aren't abusing the workqueue API by using
it for the wrong usecase.

Setup:

The system watchdog uses a delayed-work (1 second) for petting the
watchdog (resetting its counter) and if the work doesn't reset the
counters in time (another 1 second), the watchdog resets the system.

Petting-time: 1 second
Watchdog Reset-time: 2 seconds

The wq is allocated with:
        wdog_wq = alloc_workqueue("wdog", WQ_HIGHPRI, 0);

The watchdog's work-handler looks like this:

static void pet_watchdog_work(struct work_struct *work)
{

        ...

        pet_watchdog(); //Reset its counters

        /* CONFIG_HZ=300, queuing for 1 second */
        queue_delayed_work(wdog_wq, &wdog_dwork, 300);
}

kernel: 3.10 (Yeah, you can rant me for that, but its not something I
can decide on :)

Symptoms:

- The watchdog reboots the system sometimes. It is more reproducible
  in cases where an (out-of-tree) bus enumerated over USB is suddenly
  disconnected, which leads to removal of lots of kernel devices on
  that bus and a lot of print messages as well, due to failures for
  sending any more data for those devices..

Observations:

I tried to get more into it and found this..

- The timer used by the delayed work fires at the time it was
  programmed for (checked timer->expires with value of jiffies) and
  the work-handler gets a chance to run and reset the counters pretty
  quickly after that.

- But somehow, the timer isn't programmed for the right time.

- Something is happening between the time the work-handler starts
  running and we read jiffies from the add_timer() function which gets
  called from within the queue_delayed_work().

- For example, if the value of jiffies in the pet_watchdog_work()
  handler (before calling queue_delayed_work()) is say 1000000, then
  the value of jiffies after the call to queue_delayed_work() has
  returned becomes 1000310. i.e. it sometimes increases by a value of
  over 300, which is 1 second in our setup. I have seen this delta to
  vary from 50 to 350. If it crosses 300, the watchdog resets the
  system (as it was programmed for 2 seconds).


So, we aren't able to queue the next timer in time and that causes all
these problems. I haven't concluded on why is that so..

Questions:

- I hope that the wq handler can be preempted, but can it be this bad?
- Is it fine to use the wq-handler for petting the watchdog? Or should
  that only be done with help of interrupt-handlers?
- Any other clues you can give which can help us figure out what's
  going on?

Thanks in advance and sorry to bother you :)

-- 
viresh

[toc] | [next] | [standalone]


#1435511

FromTejun Heo <tj@kernel.org>
Date2016-07-01 19:30 +0200
Message-ID<rQaqm-ZW-21@gated-at.bofh.it>
In reply to#1435502
Hello, Viresh.

On Fri, Jul 01, 2016 at 09:59:59AM -0700, Viresh Kumar wrote:
> The system watchdog uses a delayed-work (1 second) for petting the
> watchdog (resetting its counter) and if the work doesn't reset the
> counters in time (another 1 second), the watchdog resets the system.
> 
> Petting-time: 1 second
> Watchdog Reset-time: 2 seconds
> 
> The wq is allocated with:
>         wdog_wq = alloc_workqueue("wdog", WQ_HIGHPRI, 0);

You probably want WQ_MEM_RECLAIM there to guarantee that it can run
quickly under memory pressure.  In reality, this shouldn't matter too
much as there aren't many competing highpri work items and thus it's
likely that there are ready highpri workers waiting for work items.

> The watchdog's work-handler looks like this:
> 
> static void pet_watchdog_work(struct work_struct *work)
> {
> 
>         ...
> 
>         pet_watchdog(); //Reset its counters
> 
>         /* CONFIG_HZ=300, queuing for 1 second */
>         queue_delayed_work(wdog_wq, &wdog_dwork, 300);
> }
> 
> kernel: 3.10 (Yeah, you can rant me for that, but its not something I
> can decide on :)

Android?

> Symptoms:
> 
> - The watchdog reboots the system sometimes. It is more reproducible
>   in cases where an (out-of-tree) bus enumerated over USB is suddenly
>   disconnected, which leads to removal of lots of kernel devices on
>   that bus and a lot of print messages as well, due to failures for
>   sending any more data for those devices..

I see.

> Observations:
> 
> I tried to get more into it and found this..
> 
> - The timer used by the delayed work fires at the time it was
>   programmed for (checked timer->expires with value of jiffies) and
>   the work-handler gets a chance to run and reset the counters pretty
>   quickly after that.

Hmmm...

> - But somehow, the timer isn't programmed for the right time.
> 
> - Something is happening between the time the work-handler starts
>   running and we read jiffies from the add_timer() function which gets
>   called from within the queue_delayed_work().
> 
> - For example, if the value of jiffies in the pet_watchdog_work()
>   handler (before calling queue_delayed_work()) is say 1000000, then
>   the value of jiffies after the call to queue_delayed_work() has
>   returned becomes 1000310. i.e. it sometimes increases by a value of
>   over 300, which is 1 second in our setup. I have seen this delta to
>   vary from 50 to 350. If it crosses 300, the watchdog resets the
>   system (as it was programmed for 2 seconds).

That's weird.  Once the work item starts executing, there isn't much
which can delay it.  queue_delayed_work() doesn't even take any lock
before reading jiffies.  In the failing cases, what's jiffies right
before and after pet_watchdog_work()?  Can that take long?

> So, we aren't able to queue the next timer in time and that causes all
> these problems. I haven't concluded on why is that so..
> 
> Questions:
> 
> - I hope that the wq handler can be preempted, but can it be this bad?

It doesn't get preempted more than any other kthread w/ -20 nice
value, so in most systems it shouldn't get preempted at all.

> - Is it fine to use the wq-handler for petting the watchdog? Or should
>   that only be done with help of interrupt-handlers?

It's absoultely fine but you'd prolly want WQ_HIGHPRI |
WQ_MEM_RECLAIM.

> - Any other clues you can give which can help us figure out what's
>   going on?
> 
> Thanks in advance and sorry to bother you :)

I'd watch sched TPs and see what actually is going on.  The described
scenario should work completely fine.

Thanks.

-- 
tejun

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


#1435523

FromViresh Kumar <viresh.kumar@linaro.org>
Date2016-07-01 19:40 +0200
Message-ID<rQaA2-13g-17@gated-at.bofh.it>
In reply to#1435511
Thanks for the quick reply Tejun, really appreciate it.

On 01-07-16, 12:22, Tejun Heo wrote:
> Hello, Viresh.
> 
> On Fri, Jul 01, 2016 at 09:59:59AM -0700, Viresh Kumar wrote:
> > The system watchdog uses a delayed-work (1 second) for petting the
> > watchdog (resetting its counter) and if the work doesn't reset the
> > counters in time (another 1 second), the watchdog resets the system.
> > 
> > Petting-time: 1 second
> > Watchdog Reset-time: 2 seconds
> > 
> > The wq is allocated with:
> >         wdog_wq = alloc_workqueue("wdog", WQ_HIGHPRI, 0);
> 
> You probably want WQ_MEM_RECLAIM there to guarantee that it can run
> quickly under memory pressure.  In reality, this shouldn't matter too
> much as there aren't many competing highpri work items and thus it's
> likely that there are ready highpri workers waiting for work items.

Sure. I though we should also have WQ_UNBOUND here to let the handler
run on any CPU.

> > kernel: 3.10 (Yeah, you can rant me for that, but its not something I
> > can decide on :)
> 
> Android?

Yeah.

> > - But somehow, the timer isn't programmed for the right time.
> > 
> > - Something is happening between the time the work-handler starts
> >   running and we read jiffies from the add_timer() function which gets
> >   called from within the queue_delayed_work().
> > 
> > - For example, if the value of jiffies in the pet_watchdog_work()
> >   handler (before calling queue_delayed_work()) is say 1000000, then
> >   the value of jiffies after the call to queue_delayed_work() has
> >   returned becomes 1000310. i.e. it sometimes increases by a value of
> >   over 300, which is 1 second in our setup. I have seen this delta to
> >   vary from 50 to 350. If it crosses 300, the watchdog resets the
> >   system (as it was programmed for 2 seconds).
> 
> That's weird.  Once the work item starts executing, there isn't much
> which can delay it.  queue_delayed_work() doesn't even take any lock
> before reading jiffies.  In the failing cases, what's jiffies right
> before and after pet_watchdog_work()?  Can that take long?

Have verified that and that part isn't taking long even in the cases
where we reboot..

Sometimes (not always), I have read the jiffies around the
lock_irq_save() in queue_delayed_work() and the jiffies had a delta of
300 :)

> > So, we aren't able to queue the next timer in time and that causes all
> > these problems. I haven't concluded on why is that so..
> > 
> > Questions:
> > 
> > - I hope that the wq handler can be preempted, but can it be this bad?
> 
> It doesn't get preempted more than any other kthread w/ -20 nice
> value, so in most systems it shouldn't get preempted at all.

Hmm..

> > - Is it fine to use the wq-handler for petting the watchdog? Or should
> >   that only be done with help of interrupt-handlers?
> 
> It's absoultely fine but you'd prolly want WQ_HIGHPRI |
> WQ_MEM_RECLAIM.

Sure.

> > - Any other clues you can give which can help us figure out what's
> >   going on?
> > 
> > Thanks in advance and sorry to bother you :)
> 
> I'd watch sched TPs and see what actually is going on.  The described
> scenario should work completely fine.

Hmm, I will see if I can get those in..

-- 
viresh

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


#1437900

FromViresh Kumar <viresh.kumar@linaro.org>
Date2016-07-06 20:30 +0200
Message-ID<rRZK9-4dN-13@gated-at.bofh.it>
In reply to#1435511
On 01-07-16, 12:22, Tejun Heo wrote:
> Hello, Viresh.
> 
> On Fri, Jul 01, 2016 at 09:59:59AM -0700, Viresh Kumar wrote:
> > The system watchdog uses a delayed-work (1 second) for petting the
> > watchdog (resetting its counter) and if the work doesn't reset the
> > counters in time (another 1 second), the watchdog resets the system.
> > 
> > Petting-time: 1 second
> > Watchdog Reset-time: 2 seconds
> > 
> > The wq is allocated with:
> >         wdog_wq = alloc_workqueue("wdog", WQ_HIGHPRI, 0);
> 
> You probably want WQ_MEM_RECLAIM there to guarantee that it can run
> quickly under memory pressure.  In reality, this shouldn't matter too
> much as there aren't many competing highpri work items and thus it's
> likely that there are ready highpri workers waiting for work items.
> 
> > The watchdog's work-handler looks like this:
> > 
> > static void pet_watchdog_work(struct work_struct *work)
> > {
> > 
> >         ...
> > 
> >         pet_watchdog(); //Reset its counters
> > 
> >         /* CONFIG_HZ=300, queuing for 1 second */
> >         queue_delayed_work(wdog_wq, &wdog_dwork, 300);
> > }
> > 
> > kernel: 3.10 (Yeah, you can rant me for that, but its not something I
> > can decide on :)
> 
> Android?
> 
> > Symptoms:
> > 
> > - The watchdog reboots the system sometimes. It is more reproducible
> >   in cases where an (out-of-tree) bus enumerated over USB is suddenly
> >   disconnected, which leads to removal of lots of kernel devices on
> >   that bus and a lot of print messages as well, due to failures for
> >   sending any more data for those devices..
> 
> I see.
> 
> > Observations:
> > 
> > I tried to get more into it and found this..
> > 
> > - The timer used by the delayed work fires at the time it was
> >   programmed for (checked timer->expires with value of jiffies) and
> >   the work-handler gets a chance to run and reset the counters pretty
> >   quickly after that.
> 
> Hmmm...
> 
> > - But somehow, the timer isn't programmed for the right time.
> > 
> > - Something is happening between the time the work-handler starts
> >   running and we read jiffies from the add_timer() function which gets
> >   called from within the queue_delayed_work().
> > 
> > - For example, if the value of jiffies in the pet_watchdog_work()
> >   handler (before calling queue_delayed_work()) is say 1000000, then
> >   the value of jiffies after the call to queue_delayed_work() has
> >   returned becomes 1000310. i.e. it sometimes increases by a value of
> >   over 300, which is 1 second in our setup. I have seen this delta to
> >   vary from 50 to 350. If it crosses 300, the watchdog resets the
> >   system (as it was programmed for 2 seconds).
> 
> That's weird.  Once the work item starts executing, there isn't much
> which can delay it.  queue_delayed_work() doesn't even take any lock
> before reading jiffies.  In the failing cases, what's jiffies right
> before and after pet_watchdog_work()?  Can that take long?
> 
> > So, we aren't able to queue the next timer in time and that causes all
> > these problems. I haven't concluded on why is that so..
> > 
> > Questions:
> > 
> > - I hope that the wq handler can be preempted, but can it be this bad?
> 
> It doesn't get preempted more than any other kthread w/ -20 nice
> value, so in most systems it shouldn't get preempted at all.
> 
> > - Is it fine to use the wq-handler for petting the watchdog? Or should
> >   that only be done with help of interrupt-handlers?
> 
> It's absoultely fine but you'd prolly want WQ_HIGHPRI |
> WQ_MEM_RECLAIM.
> 
> > - Any other clues you can give which can help us figure out what's
> >   going on?
> > 
> > Thanks in advance and sorry to bother you :)
> 
> I'd watch sched TPs and see what actually is going on.  The described
> scenario should work completely fine.

Okay, so I did trace what's going on the CPU for that long and I know
what it is now. The *print* messages :)

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 ?

Any other useful piece of advice/information you guys have? I see Jan,
Andrew and Steven do a bunch of stuff in printk.c to make it better
and so Cc'ing them.

-- 
viresh

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


#1437921

FromViresh Kumar <viresh.kumar@linaro.org>
Date2016-07-06 21:30 +0200
Message-ID<rS0Gd-4SS-7@gated-at.bofh.it>
In reply to#1437900
On 06-07-16, 15:23, Steven Rostedt wrote:
> On Wed, 6 Jul 2016 11:28:42 -0700
> Viresh Kumar <viresh.kumar@linaro.org> wrote:
> 
> 
> > 
> > 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.
> > 
> 
> Do you have the same issues with latest mainline, or is this only a
> 3.10 issue?

Don't have a mainline setup to reproduce this. For now, it is only on 3.10.

-- 
viresh

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


#1437924

FromSteven Rostedt <rostedt@goodmis.org>
Date2016-07-06 21:30 +0200
Message-ID<rS0Gd-4SS-9@gated-at.bofh.it>
In reply to#1437900
On Wed, 6 Jul 2016 11:28:42 -0700
Viresh Kumar <viresh.kumar@linaro.org> wrote:


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

Do you have the same issues with latest mainline, or is this only a
3.10 issue?

-- Steve

> @Jan Kara, Right ?
> 
> Any other useful piece of advice/information you guys have? I see Jan,
> Andrew and Steven do a bunch of stuff in printk.c to make it better
> and so Cc'ing them.
> 

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


#1440446

FromJan Kara <jack@suse.cz>
Date2016-07-11 12:30 +0200
Message-ID<rTGDo-5Kn-25@gated-at.bofh.it>
In reply to#1437900
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] | [prev] | [next] | [standalone]


#1440723

FromSergey Senozhatsky <sergey.senozhatsky@gmail.com>
Date2016-07-11 17:50 +0200
Message-ID<rTLD4-xi-15@gated-at.bofh.it>
In reply to#1440446
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

From"Rafael J. Wysocki" <rjw@rjwysocki.net>
Date2016-07-12 00:40 +0200
Message-ID<rTS1Q-4LO-19@gated-at.bofh.it>
In reply to#1440723
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

FromViresh Kumar <viresh.kumar@linaro.org>
Date2016-07-12 00:50 +0200
Message-ID<rTSbv-4P8-5@gated-at.bofh.it>
In reply to#1440948
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

From"Rafael J. Wysocki" <rjw@rjwysocki.net>
Date2016-07-12 14:30 +0200
Message-ID<rU4Z8-4Ol-3@gated-at.bofh.it>
In reply to#1440955
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

FromViresh Kumar <viresh.kumar@linaro.org>
Date2016-07-12 15:10 +0200
Message-ID<rU5BM-5k0-39@gated-at.bofh.it>
In reply to#1441307
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

FromPetr Mladek <pmladek@suse.com>
Date2016-07-12 16:00 +0200
Message-ID<rU6oa-5Gg-15@gated-at.bofh.it>
In reply to#1441337
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

FromViresh Kumar <viresh.kumar@linaro.org>
Date2016-07-12 16:10 +0200
Message-ID<rU6xQ-5Z5-5@gated-at.bofh.it>
In reply to#1441369
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

FromViresh Kumar <viresh.kumar@linaro.org>
Date2016-07-12 00:40 +0200
Message-ID<rTS1P-4LO-17@gated-at.bofh.it>
In reply to#1440723
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

FromSergey Senozhatsky <sergey.senozhatsky.work@gmail.com>
Date2016-07-12 11:40 +0200
Message-ID<rU2kx-32M-11@gated-at.bofh.it>
In reply to#1440949
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

FromPetr Mladek <pmladek@suse.com>
Date2016-07-12 15:00 +0200
Message-ID<rU5s5-51i-3@gated-at.bofh.it>
In reply to#1441181
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

FromViresh Kumar <viresh.kumar@linaro.org>
Date2016-07-12 15:20 +0200
Message-ID<rU5Lr-5nC-9@gated-at.bofh.it>
In reply to#1441322
+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

FromViresh Kumar <viresh.kumar@linaro.org>
Date2016-07-12 19:20 +0200
Message-ID<rU9vM-7Xj-5@gated-at.bofh.it>
In reply to#1441343
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

FromViresh Kumar <viresh.kumar@linaro.org>
Date2016-07-12 22:10 +0200
Message-ID<rUcad-1jn-7@gated-at.bofh.it>
In reply to#1441602
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]


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

Back to top | Article view | linux.kernel


csiph-web