[Query] Preemption (hogging) of the work handler

[Query] Preemption (hogging) of the work handler

[Viresh Kumar]

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

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

[Tejun Heo]

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

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

[Viresh Kumar]

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

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

[Viresh Kumar]

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

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

[Steven Rostedt]

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

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

[Viresh Kumar]

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

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

[Jan Kara]

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

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

[Sergey Senozhatsky]

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

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

[Viresh Kumar]

Hi Jan,

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

Yeah, I saw these patches on last Thursday. I backported all printk patches from
3.10 to mainline to my 3.10 branch and applied your patches on the top.

It did work for my case (thanks) and I wanted to give a Tested-by on the thread
[1], but by that time it was late Friday for me :)

Though I saw a issue with that.

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

On my system, the excessive printing happens during suspend/resume and this
happened after all the non-boot CPUs were offlined. So, only CPU 0 was left and
that was doing printing for a long time and so these errors :)

It resulted in missing some print messages eventually as the scheduler probably
didn't schedule this thread for sometime after that.

Will it be fine to get the priority of this kthread to a somewhat lower value,
etc ?

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

Thanks, that will be a good thing to have. I am currently backport 100+ patches
from 3.10 to mainline for printk :)

Please send them to me (please make sure that you send all the patches touching
drivers/printk/ after 3.12, so that I am not left solving merge conflicts for
ever :).

-- 
viresh

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

[Viresh Kumar]

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

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

[Rafael J. Wysocki]

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

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

[Viresh Kumar]

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

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

[Sergey Senozhatsky]

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

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

[Rafael J. Wysocki]

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

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

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

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

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

Thanks,
Rafael

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

[Petr Mladek]

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

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

[Viresh Kumar]

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

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

Any clues on why that can happen ?

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

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

-- 
viresh

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

[Viresh Kumar]

+Rafael and linux-pm to this thread :)

On 12-07-16, 14:52, Petr Mladek wrote:
> On Tue 2016-07-12 18:38:05, Sergey Senozhatsky wrote:
> > Hello,
> > 
> > On (07/11/16 15:35), Viresh Kumar wrote:
> > [..]
> > > Sometimes, the platform doesn't come back after suspend. I have tried
> > > enabling no-console-suspend and the last line it prints is:
> > > 
> > >         Disabling non-boot CPUs
> 
> I guess that the printk() kthread is not longer scheduled when there
> is only one CPU left.

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

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

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

        error = suspend_ops->enter(state);

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

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

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

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

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

-- 
viresh

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

[Petr Mladek]

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

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

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

Does it help to enable "no_console_suspend" please?


Best Regards,
Petr

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

[Sergey Senozhatsky]

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
> 

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

[Viresh Kumar]

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

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

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

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

> Does it help to enable "no_console_suspend" please?

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

-- 
viresh

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

[Viresh Kumar]

[-- Attachment #1: Type: text/plain, Size: 967 bytes --]

Hi Sergey,

On 12-07-16, 23:03, Sergey Senozhatsky wrote:
> Thanks, Petr.
> 
> 
> so, I'm looking at this thing now:

Thanks. Though just to mention, I have seen this only once yet :)

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

My setup currently looks like this:
- 3.10
- + all printk patches from 3.10 to mainline
- + your patches
- Attaching my printk.c, so you can see the current state.

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

I will try that today.

-- 
viresh

[-- Attachment #2: printk.c --]
[-- Type: text/x-csrc, Size: 88106 bytes --]

/*
 *  linux/kernel/printk.c
 *
 *  Copyright (C) 1991, 1992  Linus Torvalds
 *
 * Modified to make sys_syslog() more flexible: added commands to
 * return the last 4k of kernel messages, regardless of whether
 * they've been read or not.  Added option to suppress kernel printk's
 * to the console.  Added hook for sending the console messages
 * elsewhere, in preparation for a serial line console (someday).
 * Ted Ts'o, 2/11/93.
 * Modified for sysctl support, 1/8/97, Chris Horn.
 * Fixed SMP synchronization, 08/08/99, Manfred Spraul
 *     manfred@colorfullife.com
 * Rewrote bits to get rid of console_lock
 *	01Mar01 Andrew Morton
 */

#include <linux/kernel.h>
#include <linux/mm.h>
#include <linux/tty.h>
#include <linux/tty_driver.h>
#include <linux/console.h>
#include <linux/init.h>
#include <linux/jiffies.h>
#include <linux/nmi.h>
#include <linux/module.h>
#include <linux/moduleparam.h>
#include <linux/delay.h>
#include <linux/smp.h>
#include <linux/security.h>
#include <linux/bootmem.h>
#include <linux/memblock.h>
#include <linux/aio.h>
#include <linux/syscalls.h>
#include <linux/kexec.h>
#include <linux/kdb.h>
#include <linux/ratelimit.h>
#include <linux/kmsg_dump.h>
#include <linux/syslog.h>
#include <linux/cpu.h>
#include <linux/notifier.h>
#include <linux/rculist.h>
#include <linux/poll.h>
#include <linux/irq_work.h>
#include <linux/utsname.h>
#include <linux/ctype.h>
#include <linux/uio.h>
#include <linux/kthread.h>
#include <linux/sched/rt.h>

#include <asm/uaccess.h>
#include <asm-generic/sections.h>

#define CREATE_TRACE_POINTS
#include <trace/events/printk.h>

#include "console_cmdline.h"
#include "braille.h"
#include "internal.h"

#ifdef CONFIG_EARLY_PRINTK_DIRECT
extern void printascii(char *);
#endif

int console_printk[4] = {
	CONSOLE_LOGLEVEL_DEFAULT,	/* console_loglevel */
	MESSAGE_LOGLEVEL_DEFAULT,	/* default_message_loglevel */
	CONSOLE_LOGLEVEL_MIN,		/* minimum_console_loglevel */
	CONSOLE_LOGLEVEL_DEFAULT,	/* default_console_loglevel */
};

/*
 * Low level drivers may need that to know if they can schedule in
 * their unblank() callback or not. So let's export it.
 */
int oops_in_progress;
EXPORT_SYMBOL(oops_in_progress);

/*
 * console_sem protects the console_drivers list, and also
 * provides serialisation for access to the entire console
 * driver system.
 */
static DEFINE_SEMAPHORE(console_sem);
struct console *console_drivers;
EXPORT_SYMBOL_GPL(console_drivers);

#ifdef CONFIG_LOCKDEP
static struct lockdep_map console_lock_dep_map = {
	.name = "console_lock"
};
#endif

/*
 * Number of registered extended console drivers.
 *
 * If extended consoles are present, in-kernel cont reassembly is disabled
 * and each fragment is stored as a separate log entry with proper
 * continuation flag so that every emitted message has full metadata.  This
 * doesn't change the result for regular consoles or /proc/kmsg.  For
 * /dev/kmsg, as long as the reader concatenates messages according to
 * consecutive continuation flags, the end result should be the same too.
 */
static int nr_ext_console_drivers;

/*
 * Helper macros to handle lockdep when locking/unlocking console_sem. We use
 * macros instead of functions so that _RET_IP_ contains useful information.
 */
#define down_console_sem() do { \
	down(&console_sem);\
	mutex_acquire(&console_lock_dep_map, 0, 0, _RET_IP_);\
} while (0)

static int __down_trylock_console_sem(unsigned long ip)
{
	if (down_trylock(&console_sem))
		return 1;
	mutex_acquire(&console_lock_dep_map, 0, 1, ip);
	return 0;
}
#define down_trylock_console_sem() __down_trylock_console_sem(_RET_IP_)

#define up_console_sem() do { \
	mutex_release(&console_lock_dep_map, 1, _RET_IP_);\
	up(&console_sem);\
} while (0)

/*
 * This is used for debugging the mess that is the VT code by
 * keeping track if we have the console semaphore held. It's
 * definitely not the perfect debug tool (we don't know if _WE_
 * hold it and are racing, but it helps tracking those weird code
 * paths in the console code where we end up in places I want
 * locked without the console sempahore held).
 */
static int console_locked, console_suspended;

/*
 * If exclusive_console is non-NULL then only this console is to be printed to.
 */
static struct console *exclusive_console;

/*
 *	Array of consoles built from command line options (console=)
 */

#define MAX_CMDLINECONSOLES 8

static struct console_cmdline console_cmdline[MAX_CMDLINECONSOLES];

static int selected_console = -1;
static int preferred_console = -1;
int console_set_on_cmdline;
EXPORT_SYMBOL(console_set_on_cmdline);

/* Flag: console code may call schedule() */
static int console_may_schedule;

/*
 * The printk log buffer consists of a chain of concatenated variable
 * length records. Every record starts with a record header, containing
 * the overall length of the record.
 *
 * The heads to the first and last entry in the buffer, as well as the
 * sequence numbers of these entries are maintained when messages are
 * stored.
 *
 * If the heads indicate available messages, the length in the header
 * tells the start next message. A length == 0 for the next message
 * indicates a wrap-around to the beginning of the buffer.
 *
 * Every record carries the monotonic timestamp in microseconds, as well as
 * the standard userspace syslog level and syslog facility. The usual
 * kernel messages use LOG_KERN; userspace-injected messages always carry
 * a matching syslog facility, by default LOG_USER. The origin of every
 * message can be reliably determined that way.
 *
 * The human readable log message directly follows the message header. The
 * length of the message text is stored in the header, the stored message
 * is not terminated.
 *
 * Optionally, a message can carry a dictionary of properties (key/value pairs),
 * to provide userspace with a machine-readable message context.
 *
 * Examples for well-defined, commonly used property names are:
 *   DEVICE=b12:8               device identifier
 *                                b12:8         block dev_t
 *                                c127:3        char dev_t
 *                                n8            netdev ifindex
 *                                +sound:card0  subsystem:devname
 *   SUBSYSTEM=pci              driver-core subsystem name
 *
 * Valid characters in property names are [a-zA-Z0-9.-_]. The plain text value
 * follows directly after a '=' character. Every property is terminated by
 * a '\0' character. The last property is not terminated.
 *
 * Example of a message structure:
 *   0000  ff 8f 00 00 00 00 00 00      monotonic time in nsec
 *   0008  34 00                        record is 52 bytes long
 *   000a        0b 00                  text is 11 bytes long
 *   000c              1f 00            dictionary is 23 bytes long
 *   000e                    03 00      LOG_KERN (facility) LOG_ERR (level)
 *   0010  69 74 27 73 20 61 20 6c      "it's a l"
 *         69 6e 65                     "ine"
 *   001b           44 45 56 49 43      "DEVIC"
 *         45 3d 62 38 3a 32 00 44      "E=b8:2\0D"
 *         52 49 56 45 52 3d 62 75      "RIVER=bu"
 *         67                           "g"
 *   0032     00 00 00                  padding to next message header
 *
 * The 'struct printk_log' buffer header must never be directly exported to
 * userspace, it is a kernel-private implementation detail that might
 * need to be changed in the future, when the requirements change.
 *
 * /dev/kmsg exports the structured data in the following line format:
 *   "<level>,<sequnum>,<timestamp>,<contflag>[,additional_values, ... ];<message text>\n"
 *
 * Users of the export format should ignore possible additional values
 * separated by ',', and find the message after the ';' character.
 *
 * The optional key/value pairs are attached as continuation lines starting
 * with a space character and terminated by a newline. All possible
 * non-prinatable characters are escaped in the "\xff" notation.
 */

enum log_flags {
	LOG_NOCONS	= 1,	/* already flushed, do not print to console */
	LOG_NEWLINE	= 2,	/* text ended with a newline */
	LOG_PREFIX	= 4,	/* text started with a prefix */
	LOG_CONT	= 8,	/* text is a fragment of a continuation line */
};

struct printk_log {
	u64 ts_nsec;		/* timestamp in nanoseconds */
	u16 len;		/* length of entire record */
	u16 text_len;		/* length of text buffer */
	u16 dict_len;		/* length of dictionary buffer */
	u8 facility;		/* syslog facility */
	u8 flags:5;		/* internal record flags */
	u8 level:3;		/* syslog level */
}
#ifdef CONFIG_HAVE_EFFICIENT_UNALIGNED_ACCESS
__packed __aligned(4)
#endif
;

/*
 * The logbuf_lock protects kmsg buffer, indices, counters.  This can be taken
 * within the scheduler's rq lock. It must be released before calling
 * console_unlock() or anything else that might wake up a process.
 */
DEFINE_RAW_SPINLOCK(logbuf_lock);

#ifdef CONFIG_PRINTK
DECLARE_WAIT_QUEUE_HEAD(log_wait);
/* the next printk record to read by syslog(READ) or /proc/kmsg */
static u64 syslog_seq;
static u32 syslog_idx;
static enum log_flags syslog_prev;
static size_t syslog_partial;

/* index and sequence number of the first record stored in the buffer */
static u64 log_first_seq;
static u32 log_first_idx;

/* index and sequence number of the next record to store in the buffer */
static u64 log_next_seq;
static u32 log_next_idx;

/* the next printk record to write to the console */
static u64 console_seq;
static u32 console_idx;
static enum log_flags console_prev;

/* the next printk record to read after the last 'clear' command */
static u64 clear_seq;
static u32 clear_idx;

#define PREFIX_MAX		32
#define LOG_LINE_MAX		(1024 - PREFIX_MAX)

#define LOG_LEVEL(v)		((v) & 0x07)
#define LOG_FACILITY(v)		((v) >> 3 & 0xff)

/* record buffer */
#define LOG_ALIGN __alignof__(struct printk_log)
#define __LOG_BUF_LEN (1 << CONFIG_LOG_BUF_SHIFT)
static char __log_buf[__LOG_BUF_LEN] __aligned(LOG_ALIGN);
static char *log_buf = __log_buf;
static u32 log_buf_len = __LOG_BUF_LEN;

/* Control whether printing to console must be synchronous. */
static bool __read_mostly printk_sync = false;
/* Printing kthread for async printk */
static struct task_struct *printk_kthread;
/* When `true' printing thread has messages to print */
static bool printk_kthread_need_flush_console;

static inline bool can_printk_async(void)
{
	return !printk_sync && printk_kthread;
}

/* Return log buffer address */
char *log_buf_addr_get(void)
{
	return log_buf;
}

/* Return log buffer size */
u32 log_buf_len_get(void)
{
	return log_buf_len;
}

/* human readable text of the record */
static char *log_text(const struct printk_log *msg)
{
	return (char *)msg + sizeof(struct printk_log);
}

/* optional key/value pair dictionary attached to the record */
static char *log_dict(const struct printk_log *msg)
{
	return (char *)msg + sizeof(struct printk_log) + msg->text_len;
}

/* get record by index; idx must point to valid msg */
static struct printk_log *log_from_idx(u32 idx)
{
	struct printk_log *msg = (struct printk_log *)(log_buf + idx);

	/*
	 * A length == 0 record is the end of buffer marker. Wrap around and
	 * read the message at the start of the buffer.
	 */
	if (!msg->len)
		return (struct printk_log *)log_buf;
	return msg;
}

/* get next record; idx must point to valid msg */
static u32 log_next(u32 idx)
{
	struct printk_log *msg = (struct printk_log *)(log_buf + idx);

	/* length == 0 indicates the end of the buffer; wrap */
	/*
	 * A length == 0 record is the end of buffer marker. Wrap around and
	 * read the message at the start of the buffer as *this* one, and
	 * return the one after that.
	 */
	if (!msg->len) {
		msg = (struct printk_log *)log_buf;
		return msg->len;
	}
	return idx + msg->len;
}

/*
 * Check whether there is enough free space for the given message.
 *
 * The same values of first_idx and next_idx mean that the buffer
 * is either empty or full.
 *
 * If the buffer is empty, we must respect the position of the indexes.
 * They cannot be reset to the beginning of the buffer.
 */
static int logbuf_has_space(u32 msg_size, bool empty)
{
	u32 free;

	if (log_next_idx > log_first_idx || empty)
		free = max(log_buf_len - log_next_idx, log_first_idx);
	else
		free = log_first_idx - log_next_idx;

	/*
	 * We need space also for an empty header that signalizes wrapping
	 * of the buffer.
	 */
	return free >= msg_size + sizeof(struct printk_log);
}

static int log_make_free_space(u32 msg_size)
{
	while (log_first_seq < log_next_seq &&
	       !logbuf_has_space(msg_size, false)) {
		/* drop old messages until we have enough contiguous space */
		log_first_idx = log_next(log_first_idx);
		log_first_seq++;
	}

	if (clear_seq < log_first_seq) {
		clear_seq = log_first_seq;
		clear_idx = log_first_idx;
	}

	/* sequence numbers are equal, so the log buffer is empty */
	if (logbuf_has_space(msg_size, log_first_seq == log_next_seq))
		return 0;

	return -ENOMEM;
}

/* compute the message size including the padding bytes */
static u32 msg_used_size(u16 text_len, u16 dict_len, u32 *pad_len)
{
	u32 size;

	size = sizeof(struct printk_log) + text_len + dict_len;
	*pad_len = (-size) & (LOG_ALIGN - 1);
	size += *pad_len;

	return size;
}

/*
 * Define how much of the log buffer we could take at maximum. The value
 * must be greater than two. Note that only half of the buffer is available
 * when the index points to the middle.
 */
#define MAX_LOG_TAKE_PART 4
static const char trunc_msg[] = "<truncated>";

static u32 truncate_msg(u16 *text_len, u16 *trunc_msg_len,
			u16 *dict_len, u32 *pad_len)
{
	/*
	 * The message should not take the whole buffer. Otherwise, it might
	 * get removed too soon.
	 */
	u32 max_text_len = log_buf_len / MAX_LOG_TAKE_PART;
	if (*text_len > max_text_len)
		*text_len = max_text_len;
	/* enable the warning message */
	*trunc_msg_len = strlen(trunc_msg);
	/* disable the "dict" completely */
	*dict_len = 0;
	/* compute the size again, count also the warning message */
	return msg_used_size(*text_len + *trunc_msg_len, 0, pad_len);
}

/* insert record into the buffer, discard old ones, update heads */
static int log_store(int facility, int level,
		     enum log_flags flags, u64 ts_nsec,
		     const char *dict, u16 dict_len,
		     const char *text, u16 text_len)
{
	struct printk_log *msg;
	u32 size, pad_len;
	u16 trunc_msg_len = 0;

	/* number of '\0' padding bytes to next message */
	size = msg_used_size(text_len, dict_len, &pad_len);

	if (log_make_free_space(size)) {
		/* truncate the message if it is too long for empty buffer */
		size = truncate_msg(&text_len, &trunc_msg_len,
				    &dict_len, &pad_len);
		/* survive when the log buffer is too small for trunc_msg */
		if (log_make_free_space(size))
			return 0;
	}

	if (log_next_idx + size + sizeof(struct printk_log) > log_buf_len) {
		/*
		 * This message + an additional empty header does not fit
		 * at the end of the buffer. Add an empty header with len == 0
		 * to signify a wrap around.
		 */
		memset(log_buf + log_next_idx, 0, sizeof(struct printk_log));
		log_next_idx = 0;
	}

	/* fill message */
	msg = (struct printk_log *)(log_buf + log_next_idx);
	memcpy(log_text(msg), text, text_len);
	msg->text_len = text_len;
	if (trunc_msg_len) {
		memcpy(log_text(msg) + text_len, trunc_msg, trunc_msg_len);
		msg->text_len += trunc_msg_len;
	}
	memcpy(log_dict(msg), dict, dict_len);
	msg->dict_len = dict_len;
	msg->facility = facility;
	msg->level = level & 7;
	msg->flags = flags & 0x1f;
	if (ts_nsec > 0)
		msg->ts_nsec = ts_nsec;
	else
		msg->ts_nsec = local_clock();
	memset(log_dict(msg) + dict_len, 0, pad_len);
	msg->len = size;

	/* insert message */
	log_next_idx += msg->len;
	log_next_seq++;

	return msg->text_len;
}

int dmesg_restrict = IS_ENABLED(CONFIG_SECURITY_DMESG_RESTRICT);

static int syslog_action_restricted(int type)
{
	if (dmesg_restrict)
		return 1;
	/*
	 * Unless restricted, we allow "read all" and "get buffer size"
	 * for everybody.
	 */
	return type != SYSLOG_ACTION_READ_ALL &&
	       type != SYSLOG_ACTION_SIZE_BUFFER;
}

int check_syslog_permissions(int type, int source)
{
	/*
	 * If this is from /proc/kmsg and we've already opened it, then we've
	 * already done the capabilities checks at open time.
	 */
	if (source == SYSLOG_FROM_PROC && type != SYSLOG_ACTION_OPEN)
		goto ok;

	if (syslog_action_restricted(type)) {
		if (capable(CAP_SYSLOG))
			goto ok;
		/*
		 * For historical reasons, accept CAP_SYS_ADMIN too, with
		 * a warning.
		 */
		if (capable(CAP_SYS_ADMIN)) {
			pr_warn_once("%s (%d): Attempt to access syslog with "
				     "CAP_SYS_ADMIN but no CAP_SYSLOG "
				     "(deprecated).\n",
				 current->comm, task_pid_nr(current));
			goto ok;
		}
		return -EPERM;
	}
ok:
	return security_syslog(type);
}

static void append_char(char **pp, char *e, char c)
{
	if (*pp < e)
		*(*pp)++ = c;
}

static ssize_t msg_print_ext_header(char *buf, size_t size,
				    struct printk_log *msg, u64 seq,
				    enum log_flags prev_flags)
{
	u64 ts_usec = msg->ts_nsec;
	char cont = '-';

	do_div(ts_usec, 1000);

	/*
	 * If we couldn't merge continuation line fragments during the print,
	 * export the stored flags to allow an optional external merge of the
	 * records. Merging the records isn't always neccessarily correct, like
	 * when we hit a race during printing. In most cases though, it produces
	 * better readable output. 'c' in the record flags mark the first
	 * fragment of a line, '+' the following.
	 */
	if (msg->flags & LOG_CONT && !(prev_flags & LOG_CONT))
		cont = 'c';
	else if ((msg->flags & LOG_CONT) ||
		 ((prev_flags & LOG_CONT) && !(msg->flags & LOG_PREFIX)))
		cont = '+';

	return scnprintf(buf, size, "%u,%llu,%llu,%c;",
		       (msg->facility << 3) | msg->level, seq, ts_usec, cont);
}

static ssize_t msg_print_ext_body(char *buf, size_t size,
				  char *dict, size_t dict_len,
				  char *text, size_t text_len)
{
	char *p = buf, *e = buf + size;
	size_t i;

	/* escape non-printable characters */
	for (i = 0; i < text_len; i++) {
		unsigned char c = text[i];

		if (c < ' ' || c >= 127 || c == '\\')
			p += scnprintf(p, e - p, "\\x%02x", c);
		else
			append_char(&p, e, c);
	}
	append_char(&p, e, '\n');

	if (dict_len) {
		bool line = true;

		for (i = 0; i < dict_len; i++) {
			unsigned char c = dict[i];

			if (line) {
				append_char(&p, e, ' ');
				line = false;
			}

			if (c == '\0') {
				append_char(&p, e, '\n');
				line = true;
				continue;
			}

			if (c < ' ' || c >= 127 || c == '\\') {
				p += scnprintf(p, e - p, "\\x%02x", c);
				continue;
			}

			append_char(&p, e, c);
		}
		append_char(&p, e, '\n');
	}

	return p - buf;
}

/* /dev/kmsg - userspace message inject/listen interface */
struct devkmsg_user {
	u64 seq;
	u32 idx;
	enum log_flags prev;
	struct mutex lock;
	char buf[CONSOLE_EXT_LOG_MAX];
};

static ssize_t devkmsg_writev(struct kiocb *iocb, const struct iovec *iv,
			      unsigned long count, loff_t pos)
{
	char *buf, *line;
	int i;
	int level = default_message_loglevel;
	int facility = 1;	/* LOG_USER */
	size_t len = iov_length(iv, count);
	ssize_t ret = len;

	if (len > LOG_LINE_MAX)
		return -EINVAL;
	buf = kmalloc(len+1, GFP_KERNEL);
	if (buf == NULL)
		return -ENOMEM;

	line = buf;
	for (i = 0; i < count; i++) {
		if (copy_from_user(line, iv[i].iov_base, iv[i].iov_len)) {
			ret = -EFAULT;
			goto out;
		}
		line += iv[i].iov_len;
	}

	/*
	 * Extract and skip the syslog prefix <[0-9]*>. Coming from userspace
	 * the decimal value represents 32bit, the lower 3 bit are the log
	 * level, the rest are the log facility.
	 *
	 * If no prefix or no userspace facility is specified, we
	 * enforce LOG_USER, to be able to reliably distinguish
	 * kernel-generated messages from userspace-injected ones.
	 */
	line = buf;
	if (line[0] == '<') {
		char *endp = NULL;
		unsigned int u;

		u = simple_strtoul(line + 1, &endp, 10);
		if (endp && endp[0] == '>') {
			level = LOG_LEVEL(u);
			if (LOG_FACILITY(u) != 0)
				facility = LOG_FACILITY(u);
			endp++;
			len -= endp - line;
			line = endp;
		}
	}
	line[len] = '\0';

	printk_emit(facility, level, NULL, 0, "%s", line);
out:
	kfree(buf);
	return ret;
}

static ssize_t devkmsg_read(struct file *file, char __user *buf,
			    size_t count, loff_t *ppos)
{
	struct devkmsg_user *user = file->private_data;
	struct printk_log *msg;
	size_t len;
	ssize_t ret;

	if (!user)
		return -EBADF;

	ret = mutex_lock_interruptible(&user->lock);
	if (ret)
		return ret;
	raw_spin_lock_irq(&logbuf_lock);
	while (user->seq == log_next_seq) {
		if (file->f_flags & O_NONBLOCK) {
			ret = -EAGAIN;
			raw_spin_unlock_irq(&logbuf_lock);
			goto out;
		}

		raw_spin_unlock_irq(&logbuf_lock);
		ret = wait_event_interruptible(log_wait,
					       user->seq != log_next_seq);
		if (ret)
			goto out;
		raw_spin_lock_irq(&logbuf_lock);
	}

	if (user->seq < log_first_seq) {
		/* our last seen message is gone, return error and reset */
		user->idx = log_first_idx;
		user->seq = log_first_seq;
		ret = -EPIPE;
		raw_spin_unlock_irq(&logbuf_lock);
		goto out;
	}

	msg = log_from_idx(user->idx);
	len = msg_print_ext_header(user->buf, sizeof(user->buf),
				   msg, user->seq, user->prev);
	len += msg_print_ext_body(user->buf + len, sizeof(user->buf) - len,
				  log_dict(msg), msg->dict_len,
				  log_text(msg), msg->text_len);

	user->prev = msg->flags;
	user->idx = log_next(user->idx);
	user->seq++;
	raw_spin_unlock_irq(&logbuf_lock);

	if (len > count) {
		ret = -EINVAL;
		goto out;
	}

	if (copy_to_user(buf, user->buf, len)) {
		ret = -EFAULT;
		goto out;
	}
	ret = len;
out:
	mutex_unlock(&user->lock);
	return ret;
}

static loff_t devkmsg_llseek(struct file *file, loff_t offset, int whence)
{
	struct devkmsg_user *user = file->private_data;
	loff_t ret = 0;

	if (!user)
		return -EBADF;
	if (offset)
		return -ESPIPE;

	raw_spin_lock_irq(&logbuf_lock);
	switch (whence) {
	case SEEK_SET:
		/* the first record */
		user->idx = log_first_idx;
		user->seq = log_first_seq;
		break;
	case SEEK_DATA:
		/*
		 * The first record after the last SYSLOG_ACTION_CLEAR,
		 * like issued by 'dmesg -c'. Reading /dev/kmsg itself
		 * changes no global state, and does not clear anything.
		 */
		user->idx = clear_idx;
		user->seq = clear_seq;
		break;
	case SEEK_END:
		/* after the last record */
		user->idx = log_next_idx;
		user->seq = log_next_seq;
		break;
	default:
		ret = -EINVAL;
	}
	raw_spin_unlock_irq(&logbuf_lock);
	return ret;
}

static unsigned int devkmsg_poll(struct file *file, poll_table *wait)
{
	struct devkmsg_user *user = file->private_data;
	int ret = 0;

	if (!user)
		return POLLERR|POLLNVAL;

	poll_wait(file, &log_wait, wait);

	raw_spin_lock_irq(&logbuf_lock);
	if (user->seq < log_next_seq) {
		/* return error when data has vanished underneath us */
		if (user->seq < log_first_seq)
			ret = POLLIN|POLLRDNORM|POLLERR|POLLPRI;
		else
			ret = POLLIN|POLLRDNORM;
	}
	raw_spin_unlock_irq(&logbuf_lock);

	return ret;
}

static int devkmsg_open(struct inode *inode, struct file *file)
{
	struct devkmsg_user *user;
	int err;

	/* write-only does not need any file context */
	if ((file->f_flags & O_ACCMODE) == O_WRONLY)
		return 0;

	err = check_syslog_permissions(SYSLOG_ACTION_READ_ALL,
				       SYSLOG_FROM_READER);
	if (err)
		return err;

	user = kmalloc(sizeof(struct devkmsg_user), GFP_KERNEL);
	if (!user)
		return -ENOMEM;

	mutex_init(&user->lock);

	raw_spin_lock_irq(&logbuf_lock);
	user->idx = log_first_idx;
	user->seq = log_first_seq;
	raw_spin_unlock_irq(&logbuf_lock);

	file->private_data = user;
	return 0;
}

static int devkmsg_release(struct inode *inode, struct file *file)
{
	struct devkmsg_user *user = file->private_data;

	if (!user)
		return 0;

	mutex_destroy(&user->lock);
	kfree(user);
	return 0;
}

const struct file_operations kmsg_fops = {
	.open = devkmsg_open,
	.read = devkmsg_read,
	.aio_write = devkmsg_writev,
	.llseek = devkmsg_llseek,
	.poll = devkmsg_poll,
	.release = devkmsg_release,
};

#ifdef CONFIG_KEXEC
/*
 * This appends the listed symbols to /proc/vmcore
 *
 * /proc/vmcore is used by various utilities, like crash and makedumpfile to
 * obtain access to symbols that are otherwise very difficult to locate.  These
 * symbols are specifically used so that utilities can access and extract the
 * dmesg log from a vmcore file after a crash.
 */
void log_buf_kexec_setup(void)
{
	VMCOREINFO_SYMBOL(log_buf);
	VMCOREINFO_SYMBOL(log_buf_len);
	VMCOREINFO_SYMBOL(log_first_idx);
	VMCOREINFO_SYMBOL(clear_idx);
	VMCOREINFO_SYMBOL(log_next_idx);
	/*
	 * Export struct printk_log size and field offsets. User space tools can
	 * parse it and detect any changes to structure down the line.
	 */
	VMCOREINFO_STRUCT_SIZE(printk_log);
	VMCOREINFO_OFFSET(printk_log, ts_nsec);
	VMCOREINFO_OFFSET(printk_log, len);
	VMCOREINFO_OFFSET(printk_log, text_len);
	VMCOREINFO_OFFSET(printk_log, dict_len);
}
#endif

/* requested log_buf_len from kernel cmdline */
static unsigned long __initdata new_log_buf_len;

/* we practice scaling the ring buffer by powers of 2 */
static void __init log_buf_len_update(unsigned size)
{
	if (size)
		size = roundup_pow_of_two(size);
	if (size > log_buf_len)
		new_log_buf_len = size;
}

/* save requested log_buf_len since it's too early to process it */
static int __init log_buf_len_setup(char *str)
{
	unsigned size = memparse(str, &str);

	log_buf_len_update(size);

	return 0;
}
early_param("log_buf_len", log_buf_len_setup);

#ifdef CONFIG_SMP
#define __LOG_CPU_MAX_BUF_LEN (1 << CONFIG_LOG_CPU_MAX_BUF_SHIFT)

static void __init log_buf_add_cpu(void)
{
	unsigned int cpu_extra;

	/*
	 * archs should set up cpu_possible_bits properly with
	 * set_cpu_possible() after setup_arch() but just in
	 * case lets ensure this is valid.
	 */
	if (num_possible_cpus() == 1)
		return;

	cpu_extra = (num_possible_cpus() - 1) * __LOG_CPU_MAX_BUF_LEN;

	/* by default this will only continue through for large > 64 CPUs */
	if (cpu_extra <= __LOG_BUF_LEN / 2)
		return;

	pr_info("log_buf_len individual max cpu contribution: %d bytes\n",
		__LOG_CPU_MAX_BUF_LEN);
	pr_info("log_buf_len total cpu_extra contributions: %d bytes\n",
		cpu_extra);
	pr_info("log_buf_len min size: %d bytes\n", __LOG_BUF_LEN);

	log_buf_len_update(cpu_extra + __LOG_BUF_LEN);
}
#else /* !CONFIG_SMP */
static inline void log_buf_add_cpu(void) {}
#endif /* CONFIG_SMP */

void __init setup_log_buf(int early)
{
	unsigned long flags;
	char *new_log_buf;
	int free;

	if (log_buf != __log_buf)
		return;

	if (!early && !new_log_buf_len)
		log_buf_add_cpu();

	if (!new_log_buf_len)
		return;

	if (early) {
		new_log_buf =
			memblock_virt_alloc(new_log_buf_len, LOG_ALIGN);
	} else {
		new_log_buf = memblock_virt_alloc_nopanic(new_log_buf_len,
							  LOG_ALIGN);
	}

	if (unlikely(!new_log_buf)) {
		pr_err("log_buf_len: %ld bytes not available\n",
			new_log_buf_len);
		return;
	}

	raw_spin_lock_irqsave(&logbuf_lock, flags);
	log_buf_len = new_log_buf_len;
	log_buf = new_log_buf;
	new_log_buf_len = 0;
	free = __LOG_BUF_LEN - log_next_idx;
	memcpy(log_buf, __log_buf, __LOG_BUF_LEN);
	raw_spin_unlock_irqrestore(&logbuf_lock, flags);

	pr_info("log_buf_len: %d bytes\n", log_buf_len);
	pr_info("early log buf free: %d(%d%%)\n",
		free, (free * 100) / __LOG_BUF_LEN);
}

static bool __read_mostly ignore_loglevel;

static int __init ignore_loglevel_setup(char *str)
{
	ignore_loglevel = true;
	pr_info("debug: ignoring loglevel setting.\n");

	return 0;
}

early_param("ignore_loglevel", ignore_loglevel_setup);
module_param(ignore_loglevel, bool, S_IRUGO | S_IWUSR);
MODULE_PARM_DESC(ignore_loglevel,
		 "ignore loglevel setting (prints all kernel messages to the console)");

static bool should_ignore_loglevel(int level)
{
	return (level >= console_loglevel && !ignore_loglevel);
}

#ifdef CONFIG_BOOT_PRINTK_DELAY

static int boot_delay; /* msecs delay after each printk during bootup */
static unsigned long long loops_per_msec;	/* based on boot_delay */

static int __init boot_delay_setup(char *str)
{
	unsigned long lpj;

	lpj = preset_lpj ? preset_lpj : 1000000;	/* some guess */
	loops_per_msec = (unsigned long long)lpj / 1000 * HZ;

	get_option(&str, &boot_delay);
	if (boot_delay > 10 * 1000)
		boot_delay = 0;

	pr_debug("boot_delay: %u, preset_lpj: %ld, lpj: %lu, "
		"HZ: %d, loops_per_msec: %llu\n",
		boot_delay, preset_lpj, lpj, HZ, loops_per_msec);
	return 0;
}
early_param("boot_delay", boot_delay_setup);

static void boot_delay_msec(int level)
{
	unsigned long long k;
	unsigned long timeout;

	if ((boot_delay == 0 || system_state != SYSTEM_BOOTING)
		|| should_ignore_loglevel(level)) {
		return;
	}

	k = (unsigned long long)loops_per_msec * boot_delay;

	timeout = jiffies + msecs_to_jiffies(boot_delay);
	while (k) {
		k--;
		cpu_relax();
		/*
		 * use (volatile) jiffies to prevent
		 * compiler reduction; loop termination via jiffies
		 * is secondary and may or may not happen.
		 */
		if (time_after(jiffies, timeout))
			break;
		touch_nmi_watchdog();
	}
}
#else
static inline void boot_delay_msec(int level)
{
}
#endif

static bool printk_time = IS_ENABLED(CONFIG_PRINTK_TIME);
module_param_named(time, printk_time, bool, S_IRUGO | S_IWUSR);

static size_t print_time(u64 ts, char *buf)
{
	unsigned long rem_nsec;

	if (!printk_time)
		return 0;

	rem_nsec = do_div(ts, 1000000000);

	if (!buf)
		return snprintf(NULL, 0, "[%5lu.000000] ", (unsigned long)ts);

	return sprintf(buf, "[%5lu.%06lu] ",
		       (unsigned long)ts, rem_nsec / 1000);
}

static size_t print_prefix(const struct printk_log *msg, bool syslog, char *buf)
{
	size_t len = 0;
	unsigned int prefix = (msg->facility << 3) | msg->level;

	if (syslog) {
		if (buf) {
			len += sprintf(buf, "<%u>", prefix);
		} else {
			len += 3;
			if (prefix > 999)
				len += 3;
			else if (prefix > 99)
				len += 2;
			else if (prefix > 9)
				len++;
		}
	}

	len += print_time(msg->ts_nsec, buf ? buf + len : NULL);
	return len;
}

static size_t msg_print_text(const struct printk_log *msg, enum log_flags prev,
			     bool syslog, char *buf, size_t size)
{
	const char *text = log_text(msg);
	size_t text_size = msg->text_len;
	bool prefix = true;
	bool newline = true;
	size_t len = 0;

	if ((prev & LOG_CONT) && !(msg->flags & LOG_PREFIX))
		prefix = false;

	if (msg->flags & LOG_CONT) {
		if ((prev & LOG_CONT) && !(prev & LOG_NEWLINE))
			prefix = false;

		if (!(msg->flags & LOG_NEWLINE))
			newline = false;
	}

	do {
		const char *next = memchr(text, '\n', text_size);
		size_t text_len;

		if (next) {
			text_len = next - text;
			next++;
			text_size -= next - text;
		} else {
			text_len = text_size;
		}

		if (buf) {
			if (print_prefix(msg, syslog, NULL) +
			    text_len + 1 >= size - len)
				break;

			if (prefix)
				len += print_prefix(msg, syslog, buf + len);
			memcpy(buf + len, text, text_len);
			len += text_len;
			if (next || newline)
				buf[len++] = '\n';
		} else {
			/* SYSLOG_ACTION_* buffer size only calculation */
			if (prefix)
				len += print_prefix(msg, syslog, NULL);
			len += text_len;
			if (next || newline)
				len++;
		}

		prefix = true;
		text = next;
	} while (text);

	return len;
}

static int syslog_print(char __user *buf, int size)
{
	char *text;
	struct printk_log *msg;
	int len = 0;

	text = kmalloc(LOG_LINE_MAX + PREFIX_MAX, GFP_KERNEL);
	if (!text)
		return -ENOMEM;

	while (size > 0) {
		size_t n;
		size_t skip;

		raw_spin_lock_irq(&logbuf_lock);
		if (syslog_seq < log_first_seq) {
			/* messages are gone, move to first one */
			syslog_seq = log_first_seq;
			syslog_idx = log_first_idx;
			syslog_prev = 0;
			syslog_partial = 0;
		}
		if (syslog_seq == log_next_seq) {
			raw_spin_unlock_irq(&logbuf_lock);
			break;
		}

		skip = syslog_partial;
		msg = log_from_idx(syslog_idx);
		n = msg_print_text(msg, syslog_prev, true, text,
				   LOG_LINE_MAX + PREFIX_MAX);
		if (n - syslog_partial <= size) {
			/* message fits into buffer, move forward */
			syslog_idx = log_next(syslog_idx);
			syslog_seq++;
			syslog_prev = msg->flags;
			n -= syslog_partial;
			syslog_partial = 0;
		} else if (!len){
			/* partial read(), remember position */
			n = size;
			syslog_partial += n;
		} else
			n = 0;
		raw_spin_unlock_irq(&logbuf_lock);

		if (!n)
			break;

		if (copy_to_user(buf, text + skip, n)) {
			if (!len)
				len = -EFAULT;
			break;
		}

		len += n;
		size -= n;
		buf += n;
	}

	kfree(text);
	return len;
}

static int syslog_print_all(char __user *buf, int size, bool clear)
{
	char *text;
	int len = 0;

	text = kmalloc(LOG_LINE_MAX + PREFIX_MAX, GFP_KERNEL);
	if (!text)
		return -ENOMEM;

	raw_spin_lock_irq(&logbuf_lock);
	if (buf) {
		u64 next_seq;
		u64 seq;
		u32 idx;
		enum log_flags prev;

		/*
		 * Find first record that fits, including all following records,
		 * into the user-provided buffer for this dump.
		 */
		seq = clear_seq;
		idx = clear_idx;
		prev = 0;
		while (seq < log_next_seq) {
			struct printk_log *msg = log_from_idx(idx);

			len += msg_print_text(msg, prev, true, NULL, 0);
			prev = msg->flags;
			idx = log_next(idx);
			seq++;
		}

		/* move first record forward until length fits into the buffer */
		seq = clear_seq;
		idx = clear_idx;
		prev = 0;
		while (len > size && seq < log_next_seq) {
			struct printk_log *msg = log_from_idx(idx);

			len -= msg_print_text(msg, prev, true, NULL, 0);
			prev = msg->flags;
			idx = log_next(idx);
			seq++;
		}

		/* last message fitting into this dump */
		next_seq = log_next_seq;

		len = 0;
		while (len >= 0 && seq < next_seq) {
			struct printk_log *msg = log_from_idx(idx);
			int textlen;

			textlen = msg_print_text(msg, prev, true, text,
						 LOG_LINE_MAX + PREFIX_MAX);
			if (textlen < 0) {
				len = textlen;
				break;
			}
			idx = log_next(idx);
			seq++;
			prev = msg->flags;

			raw_spin_unlock_irq(&logbuf_lock);
			if (copy_to_user(buf + len, text, textlen))
				len = -EFAULT;
			else
				len += textlen;
			raw_spin_lock_irq(&logbuf_lock);

			if (seq < log_first_seq) {
				/* messages are gone, move to next one */
				seq = log_first_seq;
				idx = log_first_idx;
				prev = 0;
			}
		}
	}

	if (clear) {
		clear_seq = log_next_seq;
		clear_idx = log_next_idx;
	}
	raw_spin_unlock_irq(&logbuf_lock);

	kfree(text);
	return len;
}

int do_syslog(int type, char __user *buf, int len, int source)
{
	bool clear = false;
	static int saved_console_loglevel = LOGLEVEL_DEFAULT;
	int error;

	error = check_syslog_permissions(type, source);
	if (error)
		goto out;

	switch (type) {
	case SYSLOG_ACTION_CLOSE:	/* Close log */
		break;
	case SYSLOG_ACTION_OPEN:	/* Open log */
		break;
	case SYSLOG_ACTION_READ:	/* Read from log */
		error = -EINVAL;
		if (!buf || len < 0)
			goto out;
		error = 0;
		if (!len)
			goto out;
		if (!access_ok(VERIFY_WRITE, buf, len)) {
			error = -EFAULT;
			goto out;
		}
		error = wait_event_interruptible(log_wait,
						 syslog_seq != log_next_seq);
		if (error)
			goto out;
		error = syslog_print(buf, len);
		break;
	/* Read/clear last kernel messages */
	case SYSLOG_ACTION_READ_CLEAR:
		clear = true;
		/* FALL THRU */
	/* Read last kernel messages */
	case SYSLOG_ACTION_READ_ALL:
		error = -EINVAL;
		if (!buf || len < 0)
			goto out;
		error = 0;
		if (!len)
			goto out;
		if (!access_ok(VERIFY_WRITE, buf, len)) {
			error = -EFAULT;
			goto out;
		}
		error = syslog_print_all(buf, len, clear);
		break;
	/* Clear ring buffer */
	case SYSLOG_ACTION_CLEAR:
		syslog_print_all(NULL, 0, true);
		break;
	/* Disable logging to console */
	case SYSLOG_ACTION_CONSOLE_OFF:
		if (saved_console_loglevel == LOGLEVEL_DEFAULT)
			saved_console_loglevel = console_loglevel;
		console_loglevel = minimum_console_loglevel;
		break;
	/* Enable logging to console */
	case SYSLOG_ACTION_CONSOLE_ON:
		if (saved_console_loglevel != LOGLEVEL_DEFAULT) {
			console_loglevel = saved_console_loglevel;
			saved_console_loglevel = LOGLEVEL_DEFAULT;
		}
		break;
	/* Set level of messages printed to console */
	case SYSLOG_ACTION_CONSOLE_LEVEL:
		error = -EINVAL;
		if (len < 1 || len > 8)
			goto out;
		if (len < minimum_console_loglevel)
			len = minimum_console_loglevel;
		console_loglevel = len;
		/* Implicitly re-enable logging to console */
		saved_console_loglevel = LOGLEVEL_DEFAULT;
		error = 0;
		break;
	/* Number of chars in the log buffer */
	case SYSLOG_ACTION_SIZE_UNREAD:
		raw_spin_lock_irq(&logbuf_lock);
		if (syslog_seq < log_first_seq) {
			/* messages are gone, move to first one */
			syslog_seq = log_first_seq;
			syslog_idx = log_first_idx;
			syslog_prev = 0;
			syslog_partial = 0;
		}
		if (source == SYSLOG_FROM_PROC) {
			/*
			 * Short-cut for poll(/"proc/kmsg") which simply checks
			 * for pending data, not the size; return the count of
			 * records, not the length.
			 */
			error = log_next_seq - syslog_seq;
		} else {
			u64 seq = syslog_seq;
			u32 idx = syslog_idx;
			enum log_flags prev = syslog_prev;

			error = 0;
			while (seq < log_next_seq) {
				struct printk_log *msg = log_from_idx(idx);

				error += msg_print_text(msg, prev, true, NULL, 0);
				idx = log_next(idx);
				seq++;
				prev = msg->flags;
			}
			error -= syslog_partial;
		}
		raw_spin_unlock_irq(&logbuf_lock);
		break;
	/* Size of the log buffer */
	case SYSLOG_ACTION_SIZE_BUFFER:
		error = log_buf_len;
		break;
	default:
		error = -EINVAL;
		break;
	}
out:
	return error;
}

SYSCALL_DEFINE3(syslog, int, type, char __user *, buf, int, len)
{
	return do_syslog(type, buf, len, SYSLOG_FROM_READER);
}

/*
 * Call the console drivers, asking them to write out
 * log_buf[start] to log_buf[end - 1].
 * The console_lock must be held.
 */
static void call_console_drivers(int level,
				 const char *ext_text, size_t ext_len,
				 const char *text, size_t len)
{
	struct console *con;

	trace_console(text, len);

	if (!console_drivers)
		return;

	for_each_console(con) {
		if (exclusive_console && con != exclusive_console)
			continue;
		if (!(con->flags & CON_ENABLED))
			continue;
		if (!con->write)
			continue;
		if (!cpu_online(smp_processor_id()) &&
		    !(con->flags & CON_ANYTIME))
			continue;
		if (con->flags & CON_EXTENDED)
			con->write(con, ext_text, ext_len);
		else
			con->write(con, text, len);
	}
}

/*
 * Zap console related locks when oopsing.
 * To leave time for slow consoles to print a full oops,
 * only zap at most once every 30 seconds.
 */
static void zap_locks(void)
{
	static unsigned long oops_timestamp;

	if (time_after_eq(jiffies, oops_timestamp) &&
	    !time_after(jiffies, oops_timestamp + 30 * HZ))
		return;

	oops_timestamp = jiffies;

	debug_locks_off();
	/* If a crash is occurring, make sure we can't deadlock */
	raw_spin_lock_init(&logbuf_lock);
	/* And make sure that we print immediately */
	sema_init(&console_sem, 1);
}

int printk_delay_msec __read_mostly;

static inline void printk_delay(void)
{
	if (unlikely(printk_delay_msec)) {
		int m = printk_delay_msec;

		while (m--) {
			mdelay(1);
			touch_nmi_watchdog();
		}
	}
}

/*
 * Continuation lines are buffered, and not committed to the record buffer
 * until the line is complete, or a race forces it. The line fragments
 * though, are printed immediately to the consoles to ensure everything has
 * reached the console in case of a kernel crash.
 */
static struct cont {
	char buf[LOG_LINE_MAX];
	size_t len;			/* length == 0 means unused buffer */
	size_t cons;			/* bytes written to console */
	struct task_struct *owner;	/* task of first print*/
	u64 ts_nsec;			/* time of first print */
	u8 level;			/* log level of first message */
	u8 facility;			/* log facility of first message */
	enum log_flags flags;		/* prefix, newline flags */
	bool flushed:1;			/* buffer sealed and committed */
} cont;

static void cont_flush(enum log_flags flags)
{
	if (cont.flushed)
		return;
	if (cont.len == 0)
		return;

	if (cont.cons) {
		/*
		 * If a fragment of this line was directly flushed to the
		 * console; wait for the console to pick up the rest of the
		 * line. LOG_NOCONS suppresses a duplicated output.
		 */
		log_store(cont.facility, cont.level, flags | LOG_NOCONS,
			  cont.ts_nsec, NULL, 0, cont.buf, cont.len);
		cont.flags = flags;
		cont.flushed = true;
	} else {
		/*
		 * If no fragment of this line ever reached the console,
		 * just submit it to the store and free the buffer.
		 */
		log_store(cont.facility, cont.level, flags, 0,
			  NULL, 0, cont.buf, cont.len);
		cont.len = 0;
	}
}

static bool cont_add(int facility, int level, const char *text, size_t len)
{
	if (cont.len && cont.flushed)
		return false;

	/*
	 * If ext consoles are present, flush and skip in-kernel
	 * continuation.  See nr_ext_console_drivers definition.  Also, if
	 * the line gets too long, split it up in separate records.
	 */
	if (nr_ext_console_drivers || cont.len + len > sizeof(cont.buf)) {
		cont_flush(LOG_CONT);
		return false;
	}

	if (!cont.len) {
		cont.facility = facility;
		cont.level = level;
		cont.owner = current;
		cont.ts_nsec = local_clock();
		cont.flags = 0;
		cont.cons = 0;
		cont.flushed = false;
	}

	memcpy(cont.buf + cont.len, text, len);
	cont.len += len;

	if (cont.len > (sizeof(cont.buf) * 80) / 100)
		cont_flush(LOG_CONT);

	return true;
}

static size_t cont_print_text(char *text, size_t size)
{
	size_t textlen = 0;
	size_t len;

	if (cont.cons == 0 && (console_prev & LOG_NEWLINE)) {
		textlen += print_time(cont.ts_nsec, text);
		size -= textlen;
	}

	len = cont.len - cont.cons;
	if (len > 0) {
		if (len+1 > size)
			len = size-1;
		memcpy(text + textlen, cont.buf + cont.cons, len);
		textlen += len;
		cont.cons = cont.len;
	}

	if (cont.flushed) {
		if (cont.flags & LOG_NEWLINE)
			text[textlen++] = '\n';
		/* got everything, release buffer */
		cont.len = 0;
	}
	return textlen;
}

asmlinkage int vprintk_emit(int facility, int level,
			    const char *dict, size_t dictlen,
			    const char *fmt, va_list args)
{
	/* cpu currently holding logbuf_lock in this function */
	static unsigned int logbuf_cpu = UINT_MAX;
	static bool recursion_bug;
	static char textbuf[LOG_LINE_MAX];
	char *text = textbuf;
	size_t text_len = 0;
	enum log_flags lflags = 0;
	unsigned long flags;
	int this_cpu;
	int printed_len = 0;
	int nmi_message_lost;
	bool in_sched = false;
	/* do not print the KERN_CONT buffer asynchronously */
	bool has_cont_msg = false;

	if (level == LOGLEVEL_SCHED) {
		level = LOGLEVEL_DEFAULT;
		in_sched = true;
	}

	boot_delay_msec(level);
	printk_delay();

	local_irq_save(flags);
	this_cpu = smp_processor_id();

	/*
	 * Ouch, printk recursed into itself!
	 */
	if (unlikely(logbuf_cpu == this_cpu)) {
		/*
		 * If a crash is occurring during printk() on this CPU,
		 * then try to get the crash message out but make sure
		 * we can't deadlock. Otherwise just return to avoid the
		 * recursion and return - but flag the recursion so that
		 * it can be printed at the next appropriate moment:
		 */
		if (!oops_in_progress && !lockdep_recursing(current)) {
			recursion_bug = true;
			local_irq_restore(flags);
			return 0;
		}
		zap_locks();
	}

	lockdep_off();
	/* This stops the holder of console_sem just where we want him */
	raw_spin_lock(&logbuf_lock);
	logbuf_cpu = this_cpu;

	if (unlikely(recursion_bug)) {
		static const char recursion_msg[] =
			"BUG: recent printk recursion!";

		recursion_bug = false;
		/* emit KERN_CRIT message */
		printed_len += log_store(0, 2, LOG_PREFIX|LOG_NEWLINE, 0,
					 NULL, 0, recursion_msg,
					 strlen(recursion_msg));
	}

	nmi_message_lost = get_nmi_message_lost();
	if (unlikely(nmi_message_lost)) {
		text_len = scnprintf(textbuf, sizeof(textbuf),
				     "BAD LUCK: lost %d message(s) from NMI context!",
				     nmi_message_lost);
		printed_len += log_store(0, 2, LOG_PREFIX|LOG_NEWLINE, 0,
					 NULL, 0, textbuf, text_len);
	}

	/*
	 * The printf needs to come first; we need the syslog
	 * prefix which might be passed-in as a parameter.
	 */
	text_len = vscnprintf(text, sizeof(textbuf), fmt, args);

	/* mark and strip a trailing newline */
	if (text_len && text[text_len-1] == '\n') {
		text_len--;
		lflags |= LOG_NEWLINE;
	}

	/* strip kernel syslog prefix and extract log level or control flags */
	if (facility == 0) {
		int kern_level = printk_get_level(text);

		if (kern_level) {
			const char *end_of_header = printk_skip_level(text);
			switch (kern_level) {
			case '0' ... '7':
				if (level == LOGLEVEL_DEFAULT)
					level = kern_level - '0';
				/* fallthrough */
			case 'd':	/* KERN_DEFAULT */
				lflags |= LOG_PREFIX;
			}
			/*
			 * No need to check length here because vscnprintf
			 * put '\0' at the end of the string. Only valid and
			 * newly printed level is detected.
			 */
			text_len -= end_of_header - text;
			text = (char *)end_of_header;
		}
	}

#ifdef CONFIG_EARLY_PRINTK_DIRECT
	printascii(text);
#endif

	if (level == LOGLEVEL_DEFAULT)
		level = default_message_loglevel;

	if (dict)
		lflags |= LOG_PREFIX|LOG_NEWLINE;

	if (!(lflags & LOG_NEWLINE)) {
		has_cont_msg = true;

		/*
		 * Flush the conflicting buffer. An earlier newline was missing,
		 * or another task also prints continuation lines.
		 */
		if (cont.len && (lflags & LOG_PREFIX || cont.owner != current))
			cont_flush(LOG_NEWLINE);

		/* buffer line if possible, otherwise store it right away */
		if (cont_add(facility, level, text, text_len))
			printed_len += text_len;
		else
			printed_len += log_store(facility, level,
						 lflags | LOG_CONT, 0,
						 dict, dictlen, text, text_len);
	} else {
		bool stored = false;

		/*
		 * If an earlier newline was missing and it was the same task,
		 * either merge it with the current buffer and flush, or if
		 * there was a race with interrupts (prefix == true) then just
		 * flush it out and store this line separately.
		 * If the preceding printk was from a different task and missed
		 * a newline, flush and append the newline.
		 */
		if (cont.len) {
			if (cont.owner == current && !(lflags & LOG_PREFIX))
				stored = cont_add(facility, level, text,
						  text_len);
			cont_flush(LOG_NEWLINE);
			has_cont_msg = true;
		}

		if (stored)
			printed_len += text_len;
		else
			printed_len += log_store(facility, level, lflags, 0,
						 dict, dictlen, text, text_len);
	}

	logbuf_cpu = UINT_MAX;
	raw_spin_unlock(&logbuf_lock);
	lockdep_on();
	local_irq_restore(flags);

	/* If called from the scheduler, we can not call up(). */
	if (!in_sched) {
		lockdep_off();
		/*
		 * Attempt to print the messages to console asynchronously so
		 * that the kernel doesn't get stalled due to slow serial
		 * console. That can lead to softlockups, lost interrupts, or
		 * userspace timing out under heavy printing load.
		 *
		 * However we resort to synchronous printing of messages during
		 * early boot, when synchronous printing was explicitly
		 * requested by a kernel parameter, when we have a KERN_CONT
		 * buffer to print, or when console_verbose() was called to
		 * print everything during panic / oops.
		 * Unlike bust_spinlocks() and oops_in_progress,
		 * console_verbose() sets console_loglevel to MOTORMOUTH and
		 * never clears it, while oops_in_progress can go back to 0,
		 * switching printk back to async mode; we want printk to
		 * operate in sync mode once panic() occurred.
		 */
		if (console_loglevel != CONSOLE_LOGLEVEL_MOTORMOUTH &&
				can_printk_async() &&
				!has_cont_msg) {
			/* Offload printing to a schedulable context. */
			printk_kthread_need_flush_console = true;
			wake_up_process(printk_kthread);
		} else {
			/*
			 * Try to acquire and then immediately release the
			 * console semaphore.  The release will print out
			 * buffers and wake up /dev/kmsg and syslog() users.
			 */
			if (console_trylock())
				console_unlock();
		}
		lockdep_on();
	}

	return printed_len;
}
EXPORT_SYMBOL(vprintk_emit);

asmlinkage int vprintk(const char *fmt, va_list args)
{
	return vprintk_emit(0, LOGLEVEL_DEFAULT, NULL, 0, fmt, args);
}
EXPORT_SYMBOL(vprintk);

asmlinkage int printk_emit(int facility, int level,
			   const char *dict, size_t dictlen,
			   const char *fmt, ...)
{
	va_list args;
	int r;

	va_start(args, fmt);
	r = vprintk_emit(facility, level, dict, dictlen, fmt, args);
	va_end(args);

	return r;
}
EXPORT_SYMBOL(printk_emit);

int vprintk_default(const char *fmt, va_list args)
{
	int r;

#ifdef CONFIG_KGDB_KDB
	if (unlikely(kdb_trap_printk)) {
		r = vkdb_printf(KDB_MSGSRC_PRINTK, fmt, args);
		return r;
	}
#endif
	r = vprintk_emit(0, LOGLEVEL_DEFAULT, NULL, 0, fmt, args);

	return r;
}
EXPORT_SYMBOL_GPL(vprintk_default);

/**
 * printk - print a kernel message
 * @fmt: format string
 *
 * This is printk(). It can be called from any context. We want it to work.
 *
 * We try to grab the console_lock. If we succeed, it's easy - we log the
 * output and call the console drivers.  If we fail to get the semaphore, we
 * place the output into the log buffer and return. The current holder of
 * the console_sem will notice the new output in console_unlock(); and will
 * send it to the consoles before releasing the lock.
 *
 * One effect of this deferred printing is that code which calls printk() and
 * then changes console_loglevel may break. This is because console_loglevel
 * is inspected when the actual printing occurs.
 *
 * See also:
 * printf(3)
 *
 * See the vsnprintf() documentation for format string extensions over C99.
 */
asmlinkage int printk(const char *fmt, ...)
{
	va_list args;
	int r;

	va_start(args, fmt);
	r = vprintk_func(fmt, args);
	va_end(args);

	return r;
}
EXPORT_SYMBOL(printk);

#else /* CONFIG_PRINTK */

#define LOG_LINE_MAX		0
#define PREFIX_MAX		0

static u64 syslog_seq;
static u32 syslog_idx;
static u64 console_seq;
static u32 console_idx;
static enum log_flags syslog_prev;
static u64 log_first_seq;
static u32 log_first_idx;
static u64 log_next_seq;
static enum log_flags console_prev;
static struct cont {
	size_t len;
	size_t cons;
	u8 level;
	bool flushed:1;
} cont;
static char *log_text(const struct printk_log *msg) { return NULL; }
static char *log_dict(const struct printk_log *msg) { return NULL; }
static struct printk_log *log_from_idx(u32 idx) { return NULL; }
static u32 log_next(u32 idx) { return 0; }
static ssize_t msg_print_ext_header(char *buf, size_t size,
				    struct printk_log *msg, u64 seq,
				    enum log_flags prev_flags) { return 0; }
static ssize_t msg_print_ext_body(char *buf, size_t size,
				  char *dict, size_t dict_len,
				  char *text, size_t text_len) { return 0; }
static void call_console_drivers(int level,
				 const char *ext_text, size_t ext_len,
				 const char *text, size_t len) {}
static size_t msg_print_text(const struct printk_log *msg, enum log_flags prev,
			     bool syslog, char *buf, size_t size) { return 0; }
static size_t cont_print_text(char *text, size_t size) { return 0; }
static bool should_ignore_loglevel(int level) { return false; }

/* Still needs to be defined for users */
DEFINE_PER_CPU(printk_func_t, printk_func);

#endif /* CONFIG_PRINTK */

#ifdef CONFIG_EARLY_PRINTK
struct console *early_console;

asmlinkage void early_printk(const char *fmt, ...)
{
	va_list ap;
	char buf[512];
	int n;

	if (!early_console)
		return;

	va_start(ap, fmt);
	n = vscnprintf(buf, sizeof(buf), fmt, ap);
	va_end(ap);

	early_console->write(early_console, buf, n);
}
#endif

static int __add_preferred_console(char *name, int idx, char *options,
				   char *brl_options)
{
	struct console_cmdline *c;
	int i;

	/*
	 *	See if this tty is not yet registered, and
	 *	if we have a slot free.
	 */
	for (i = 0, c = console_cmdline;
	     i < MAX_CMDLINECONSOLES && c->name[0];
	     i++, c++) {
		if (strcmp(c->name, name) == 0 && c->index == idx) {
			if (!brl_options)
				selected_console = i;
			return 0;
		}
	}
	if (i == MAX_CMDLINECONSOLES)
		return -E2BIG;
	if (!brl_options)
		selected_console = i;
	strlcpy(c->name, name, sizeof(c->name));
	c->options = options;
	braille_set_options(c, brl_options);

	c->index = idx;
	return 0;
}
/*
 * Set up a console.  Called via do_early_param() in init/main.c
 * for each "console=" parameter in the boot command line.
 */
static int __init console_setup(char *str)
{
	char buf[sizeof(console_cmdline[0].name) + 4]; /* 4 for "ttyS" */
	char *s, *options, *brl_options = NULL;
	int idx;

	if (_braille_console_setup(&str, &brl_options))
		return 1;

	/*
	 * Decode str into name, index, options.
	 */
	if (str[0] >= '0' && str[0] <= '9') {
		strcpy(buf, "ttyS");
		strncpy(buf + 4, str, sizeof(buf) - 5);
	} else {
		strncpy(buf, str, sizeof(buf) - 1);
	}
	buf[sizeof(buf) - 1] = 0;
	options = strchr(str, ',');
	if (options)
		*(options++) = 0;
#ifdef __sparc__
	if (!strcmp(str, "ttya"))
		strcpy(buf, "ttyS0");
	if (!strcmp(str, "ttyb"))
		strcpy(buf, "ttyS1");
#endif
	for (s = buf; *s; s++)
		if (isdigit(*s) || *s == ',')
			break;
	idx = simple_strtoul(s, NULL, 10);
	*s = 0;

	__add_preferred_console(buf, idx, options, brl_options);
	console_set_on_cmdline = 1;
	return 1;
}
__setup("console=", console_setup);

/**
 * add_preferred_console - add a device to the list of preferred consoles.
 * @name: device name
 * @idx: device index
 * @options: options for this console
 *
 * The last preferred console added will be used for kernel messages
 * and stdin/out/err for init.  Normally this is used by console_setup
 * above to handle user-supplied console arguments; however it can also
 * be used by arch-specific code either to override the user or more
 * commonly to provide a default console (ie from PROM variables) when
 * the user has not supplied one.
 */
int add_preferred_console(char *name, int idx, char *options)
{
	return __add_preferred_console(name, idx, options, NULL);
}

int update_console_cmdline(char *name, int idx, char *name_new, int idx_new, char *options)
{
	struct console_cmdline *c;
	int i;

	for (i = 0, c = console_cmdline;
	     i < MAX_CMDLINECONSOLES && c->name[0];
	     i++, c++)
		if (strcmp(c->name, name) == 0 && c->index == idx) {
			strlcpy(c->name, name_new, sizeof(c->name));
			c->options = options;
			c->index = idx_new;
			return i;
		}
	/* not found */
	return -1;
}

bool console_suspend_enabled = true;
EXPORT_SYMBOL(console_suspend_enabled);

static int __init console_suspend_disable(char *str)
{
	console_suspend_enabled = false;
	return 1;
}
__setup("no_console_suspend", console_suspend_disable);
module_param_named(console_suspend, console_suspend_enabled,
		bool, S_IRUGO | S_IWUSR);
MODULE_PARM_DESC(console_suspend, "suspend console during suspend"
	" and hibernate operations");


/* check current suspend/resume status of the console */
int is_console_suspended(void)
{
	return console_suspended;
}

/**
 * suspend_console - suspend the console subsystem
 *
 * This disables printk() while we go into suspend states
 */
void suspend_console(void)
{
	if (!console_suspend_enabled)
		return;
	printk("Suspending console(s) (use no_console_suspend to debug)\n");
	console_lock();
	console_suspended = 1;
	up_console_sem();
}

void resume_console(void)
{
	if (!console_suspend_enabled)
		return;
	down_console_sem();
	console_suspended = 0;
	console_unlock();
}

static void __cpuinit console_flush(struct work_struct *work)
{
	console_lock();
	console_unlock();
}

static __cpuinitdata DECLARE_WORK(console_cpu_notify_work, console_flush);

/**
 * console_cpu_notify - print deferred console messages after CPU hotplug
 * @self: notifier struct
 * @action: CPU hotplug event
 * @hcpu: unused
 *
 * If printk() is called from a CPU that is not online yet, the messages
 * will be spooled but will not show up on the console.  This function is
 * called when a new CPU comes online (or fails to come up), and ensures
 * that any such output gets printed.
 *
 * Special handling must be done for cases invoked from an atomic context,
 * as we can't be taking the console semaphore here.
 */
static int __cpuinit console_cpu_notify(struct notifier_block *self,
	unsigned long action, void *hcpu)
{
	switch (action) {
	case CPU_DEAD:
	case CPU_DOWN_FAILED:
	case CPU_UP_CANCELED:
#ifdef CONFIG_CONSOLE_FLUSH_ON_HOTPLUG
		console_lock();
		console_unlock();
#endif
		break;
	case CPU_ONLINE:
	case CPU_DYING:
		/* invoked with preemption disabled, so defer */
		if (!console_trylock())
			schedule_work(&console_cpu_notify_work);
		else
			console_unlock();
	}
	return NOTIFY_OK;
}

/**
 * console_lock - lock the console system for exclusive use.
 *
 * Acquires a lock which guarantees that the caller has
 * exclusive access to the console system and the console_drivers list.
 *
 * Can sleep, returns nothing.
 */
void console_lock(void)
{
	might_sleep();

	down_console_sem();
	if (console_suspended)
		return;
	console_locked = 1;
	console_may_schedule = 1;
}
EXPORT_SYMBOL(console_lock);

/**
 * console_trylock - try to lock the console system for exclusive use.
 *
 * Try to acquire a lock which guarantees that the caller has exclusive
 * access to the console system and the console_drivers list.
 *
 * returns 1 on success, and 0 on failure to acquire the lock.
 */
int console_trylock(void)
{
	if (down_trylock_console_sem())
		return 0;
	if (console_suspended) {
		up_console_sem();
		return 0;
	}
	console_locked = 1;
	/*
	 * When PREEMPT_COUNT disabled we can't reliably detect if it's
	 * safe to schedule (e.g. calling printk while holding a spin_lock),
	 * because preempt_disable()/preempt_enable() are just barriers there
	 * and preempt_count() is always 0.
	 *
	 * RCU read sections have a separate preemption counter when
	 * PREEMPT_RCU enabled thus we must take extra care and check
	 * rcu_preempt_depth(), otherwise RCU read sections modify
	 * preempt_count().
	 */
	console_may_schedule = !oops_in_progress &&
			preemptible() &&
			!rcu_preempt_depth();
	return 1;
}
EXPORT_SYMBOL(console_trylock);

int is_console_locked(void)
{
	return console_locked;
}

/*
 * Check if we have any console that is capable of printing while cpu is
 * booting or shutting down. Requires console_sem.
 */
static int have_callable_console(void)
{
	struct console *con;

	for_each_console(con)
		if ((con->flags & CON_ENABLED) &&
				(con->flags & CON_ANYTIME))
			return 1;

	return 0;
}

/*
 * Can we actually use the console at this time on this cpu?
 *
 * Console drivers may assume that per-cpu resources have been allocated. So
 * unless they're explicitly marked as being able to cope (CON_ANYTIME) don't
 * call them until this CPU is officially up.
 */
static inline int can_use_console(void)
{
	return cpu_online(raw_smp_processor_id()) || have_callable_console();
}

static void console_cont_flush(char *text, size_t size)
{
	unsigned long flags;
	size_t len;

	raw_spin_lock_irqsave(&logbuf_lock, flags);

	if (!cont.len)
		goto out;

	if (should_ignore_loglevel(cont.level)) {
		cont.cons = cont.len;
		if (cont.flushed)
			cont.len = 0;
		goto out;
	}

	/*
	 * We still queue earlier records, likely because the console was
	 * busy. The earlier ones need to be printed before this one, we
	 * did not flush any fragment so far, so just let it queue up.
	 */
	if (console_seq < log_next_seq && !cont.cons)
		goto out;

	len = cont_print_text(text, size);
	raw_spin_unlock(&logbuf_lock);
	stop_critical_timings();
	call_console_drivers(cont.level, NULL, 0, text, len);
	start_critical_timings();
	local_irq_restore(flags);
	return;
out:
	raw_spin_unlock_irqrestore(&logbuf_lock, flags);
}

/**
 * console_unlock - unlock the console system
 *
 * Releases the console_lock which the caller holds on the console system
 * and the console driver list.
 *
 * While the console_lock was held, console output may have been buffered
 * by printk().  If this is the case, console_unlock(); emits
 * the output prior to releasing the lock.
 *
 * If there is output waiting, we wake /dev/kmsg and syslog() users.
 *
 * console_unlock(); may be called from any context.
 */
void console_unlock(void)
{
	static char ext_text[CONSOLE_EXT_LOG_MAX];
	static char text[LOG_LINE_MAX + PREFIX_MAX];
	static u64 seen_seq;
	unsigned long flags;
	bool wake_klogd = false;
	bool do_cond_resched, retry;

	if (console_suspended) {
		up_console_sem();
		return;
	}

	/*
	 * Console drivers are called under logbuf_lock, so
	 * @console_may_schedule should be cleared before; however, we may
	 * end up dumping a lot of lines, for example, if called from
	 * console registration path, and should invoke cond_resched()
	 * between lines if allowable.  Not doing so can cause a very long
	 * scheduling stall on a slow console leading to RCU stall and
	 * softlockup warnings which exacerbate the issue with more
	 * messages practically incapacitating the system.
	 */
	do_cond_resched = console_may_schedule;
	console_may_schedule = 0;

again:
	/*
	 * We released the console_sem lock, so we need to recheck if
	 * cpu is online and (if not) is there at least one CON_ANYTIME
	 * console.
	 */
	if (!can_use_console()) {
		console_locked = 0;
		up_console_sem();
		return;
	}

	/* flush buffered message fragment immediately to console */
	console_cont_flush(text, sizeof(text));

	for (;;) {
		struct printk_log *msg;
		size_t ext_len = 0;
		size_t len;
		int level;

		raw_spin_lock_irqsave(&logbuf_lock, flags);
		if (seen_seq != log_next_seq) {
			wake_klogd = true;
			seen_seq = log_next_seq;
		}

		if (console_seq < log_first_seq) {
			len = sprintf(text, "** %u printk messages dropped ** ",
				      (unsigned)(log_first_seq - console_seq));

			/* messages are gone, move to first one */
			console_seq = log_first_seq;
			console_idx = log_first_idx;
			console_prev = 0;
		} else {
			len = 0;
		}
skip:
		if (console_seq == log_next_seq)
			break;

		msg = log_from_idx(console_idx);
		level = msg->level;
		if ((msg->flags & LOG_NOCONS) ||
				should_ignore_loglevel(level)) {
			/*
			 * Skip record we have buffered and already printed
			 * directly to the console when we received it, and
			 * record that has level above the console loglevel.
			 */
			console_idx = log_next(console_idx);
			console_seq++;
			/*
			 * We will get here again when we register a new
			 * CON_PRINTBUFFER console. Clear the flag so we
			 * will properly dump everything later.
			 */
			msg->flags &= ~LOG_NOCONS;
			console_prev = msg->flags;
			goto skip;
		}

		len += msg_print_text(msg, console_prev, false,
				      text + len, sizeof(text) - len);
		if (nr_ext_console_drivers) {
			ext_len = msg_print_ext_header(ext_text,
						sizeof(ext_text),
						msg, console_seq, console_prev);
			ext_len += msg_print_ext_body(ext_text + ext_len,
						sizeof(ext_text) - ext_len,
						log_dict(msg), msg->dict_len,
						log_text(msg), msg->text_len);
		}
		console_idx = log_next(console_idx);
		console_seq++;
		console_prev = msg->flags;
		raw_spin_unlock(&logbuf_lock);

		stop_critical_timings();	/* don't trace print latency */
		call_console_drivers(level, ext_text, ext_len, text, len);
		start_critical_timings();
		local_irq_restore(flags);

		if (do_cond_resched)
			cond_resched();
	}
	console_locked = 0;

	/* Release the exclusive_console once it is used */
	if (unlikely(exclusive_console))
		exclusive_console = NULL;

	raw_spin_unlock(&logbuf_lock);

	up_console_sem();

	/*
	 * Someone could have filled up the buffer again, so re-check if there's
	 * something to flush. In case we cannot trylock the console_sem again,
	 * there's a new owner and the console_unlock() from them will do the
	 * flush, no worries.
	 */
	raw_spin_lock(&logbuf_lock);
	retry = console_seq != log_next_seq;
	raw_spin_unlock_irqrestore(&logbuf_lock, flags);

	if (retry && console_trylock())
		goto again;

	if (wake_klogd)
		wake_up_klogd();
}
EXPORT_SYMBOL(console_unlock);

/**
 * console_conditional_schedule - yield the CPU if required
 *
 * If the console code is currently allowed to sleep, and
 * if this CPU should yield the CPU to another task, do
 * so here.
 *
 * Must be called within console_lock();.
 */
void __sched console_conditional_schedule(void)
{
	if (console_may_schedule)
		cond_resched();
}
EXPORT_SYMBOL(console_conditional_schedule);

void console_unblank(void)
{
	struct console *c;

	/*
	 * console_unblank can no longer be called in interrupt context unless
	 * oops_in_progress is set to 1..
	 */
	if (oops_in_progress) {
		if (down_trylock_console_sem() != 0)
			return;
	} else
		console_lock();

	console_locked = 1;
	console_may_schedule = 0;
	for_each_console(c)
		if ((c->flags & CON_ENABLED) && c->unblank)
			c->unblank();
	console_unlock();
}

/**
 * console_flush_on_panic - flush console content on panic
 *
 * Immediately output all pending messages no matter what.
 */
void console_flush_on_panic(void)
{
	/*
	 * If someone else is holding the console lock, trylock will fail
	 * and may_schedule may be set.  Ignore and proceed to unlock so
	 * that messages are flushed out.  As this can be called from any
	 * context and we don't want to get preempted while flushing,
	 * ensure may_schedule is cleared.
	 */
	console_trylock();
	console_may_schedule = 0;
	console_unlock();
}

/*
 * Return the console tty driver structure and its associated index
 */
struct tty_driver *console_device(int *index)
{
	struct console *c;
	struct tty_driver *driver = NULL;

	console_lock();
	for_each_console(c) {
		if (!c->device)
			continue;
		driver = c->device(c, index);
		if (driver)
			break;
	}
	console_unlock();
	return driver;
}

/*
 * Prevent further output on the passed console device so that (for example)
 * serial drivers can disable console output before suspending a port, and can
 * re-enable output afterwards.
 */
void console_stop(struct console *console)
{
	console_lock();
	console->flags &= ~CON_ENABLED;
	console_unlock();
}
EXPORT_SYMBOL(console_stop);

void console_start(struct console *console)
{
	console_lock();
	console->flags |= CON_ENABLED;
	console_unlock();
}
EXPORT_SYMBOL(console_start);

static int __read_mostly keep_bootcon;

static int __init keep_bootcon_setup(char *str)
{
	keep_bootcon = 1;
	pr_info("debug: skip boot console de-registration.\n");

	return 0;
}

early_param("keep_bootcon", keep_bootcon_setup);

/*
 * The console driver calls this routine during kernel initialization
 * to register the console printing procedure with printk() and to
 * print any messages that were printed by the kernel before the
 * console driver was initialized.
 *
 * This can happen pretty early during the boot process (because of
 * early_printk) - sometimes before setup_arch() completes - be careful
 * of what kernel features are used - they may not be initialised yet.
 *
 * There are two types of consoles - bootconsoles (early_printk) and
 * "real" consoles (everything which is not a bootconsole) which are
 * handled differently.
 *  - Any number of bootconsoles can be registered at any time.
 *  - As soon as a "real" console is registered, all bootconsoles
 *    will be unregistered automatically.
 *  - Once a "real" console is registered, any attempt to register a
 *    bootconsoles will be rejected
 */
void register_console(struct console *newcon)
{
	int i;
	unsigned long flags;
	struct console *bcon = NULL;
	struct console_cmdline *c;

	if (console_drivers)
		for_each_console(bcon)
			if (WARN(bcon == newcon,
					"console '%s%d' already registered\n",
					bcon->name, bcon->index))
				return;

	/*
	 * before we register a new CON_BOOT console, make sure we don't
	 * already have a valid console
	 */
	if (console_drivers && newcon->flags & CON_BOOT) {
		/* find the last or real console */
		for_each_console(bcon) {
			if (!(bcon->flags & CON_BOOT)) {
				pr_info("Too late to register bootconsole %s%d\n",
					newcon->name, newcon->index);
				return;
			}
		}
	}

	if (console_drivers && console_drivers->flags & CON_BOOT)
		bcon = console_drivers;

	if (preferred_console < 0 || bcon || !console_drivers)
		preferred_console = selected_console;

	if (newcon->early_setup)
		newcon->early_setup();

	/*
	 *	See if we want to use this console driver. If we
	 *	didn't select a console we take the first one
	 *	that registers here.
	 */
	if (preferred_console < 0) {
		if (newcon->index < 0)
			newcon->index = 0;
		if (newcon->setup == NULL ||
		    newcon->setup(newcon, NULL) == 0) {
			newcon->flags |= CON_ENABLED;
			if (newcon->device) {
				newcon->flags |= CON_CONSDEV;
				preferred_console = 0;
			}
		}
	}

	/*
	 *	See if this console matches one we selected on
	 *	the command line.
	 */
	for (i = 0, c = console_cmdline;
	     i < MAX_CMDLINECONSOLES && c->name[0];
	     i++, c++) {
		BUILD_BUG_ON(sizeof(c->name) != sizeof(newcon->name));
		if (strcmp(c->name, newcon->name) != 0)
			continue;
		if (newcon->index >= 0 &&
		    newcon->index != c->index)
			continue;
		if (newcon->index < 0)
			newcon->index = c->index;

		if (_braille_register_console(newcon, c))
			return;

		if (newcon->setup &&
		    newcon->setup(newcon, console_cmdline[i].options) != 0)
			break;
		newcon->flags |= CON_ENABLED;
		if (i == selected_console) {
			newcon->flags |= CON_CONSDEV;
			preferred_console = selected_console;
		}
		break;
	}

	if (!(newcon->flags & CON_ENABLED))
		return;

	/*
	 * If we have a bootconsole, and are switching to a real console,
	 * don't print everything out again, since when the boot console, and
	 * the real console are the same physical device, it's annoying to
	 * see the beginning boot messages twice
	 */
	if (bcon && ((newcon->flags & (CON_CONSDEV | CON_BOOT)) == CON_CONSDEV))
		newcon->flags &= ~CON_PRINTBUFFER;

	/*
	 *	Put this console in the list - keep the
	 *	preferred driver at the head of the list.
	 */
	console_lock();
	if ((newcon->flags & CON_CONSDEV) || console_drivers == NULL) {
		newcon->next = console_drivers;
		console_drivers = newcon;
		if (newcon->next)
			newcon->next->flags &= ~CON_CONSDEV;
	} else {
		newcon->next = console_drivers->next;
		console_drivers->next = newcon;
	}

	if (newcon->flags & CON_EXTENDED)
		if (!nr_ext_console_drivers++)
			pr_info("printk: continuation disabled due to ext consoles, expect more fragments in /dev/kmsg\n");

	if (newcon->flags & CON_PRINTBUFFER) {
		/*
		 * console_unlock(); will print out the buffered messages
		 * for us.
		 */
		raw_spin_lock_irqsave(&logbuf_lock, flags);
		console_seq = syslog_seq;
		console_idx = syslog_idx;
		console_prev = syslog_prev;
		raw_spin_unlock_irqrestore(&logbuf_lock, flags);
		/*
		 * We're about to replay the log buffer.  Only do this to the
		 * just-registered console to avoid excessive message spam to
		 * the already-registered consoles.
		 */
		exclusive_console = newcon;
	}
	console_unlock();
	console_sysfs_notify();

	/*
	 * By unregistering the bootconsoles after we enable the real console
	 * we get the "console xxx enabled" message on all the consoles -
	 * boot consoles, real consoles, etc - this is to ensure that end
	 * users know there might be something in the kernel's log buffer that
	 * went to the bootconsole (that they do not see on the real console)
	 */
	pr_info("%sconsole [%s%d] enabled\n",
		(newcon->flags & CON_BOOT) ? "boot" : "" ,
		newcon->name, newcon->index);
	if (bcon &&
	    ((newcon->flags & (CON_CONSDEV | CON_BOOT)) == CON_CONSDEV) &&
	    !keep_bootcon) {
		/* We need to iterate through all boot consoles, to make
		 * sure we print everything out, before we unregister them.
		 */
		for_each_console(bcon)
			if (bcon->flags & CON_BOOT)
				unregister_console(bcon);
	}
}
EXPORT_SYMBOL(register_console);

int unregister_console(struct console *console)
{
        struct console *a, *b;
	int res;

	pr_info("%sconsole [%s%d] disabled\n",
		(console->flags & CON_BOOT) ? "boot" : "" ,
		console->name, console->index);

	res = _braille_unregister_console(console);
	if (res)
		return res;

	res = 1;
	console_lock();
	if (console_drivers == console) {
		console_drivers=console->next;
		res = 0;
	} else if (console_drivers) {
		for (a=console_drivers->next, b=console_drivers ;
		     a; b=a, a=b->next) {
			if (a == console) {
				b->next = a->next;
				res = 0;
				break;
			}
		}
	}

	if (!res && (console->flags & CON_EXTENDED))
		nr_ext_console_drivers--;

	/*
	 * If this isn't the last console and it has CON_CONSDEV set, we
	 * need to set it on the next preferred console.
	 */
	if (console_drivers != NULL && console->flags & CON_CONSDEV)
		console_drivers->flags |= CON_CONSDEV;

	console->flags &= ~CON_ENABLED;
	console_unlock();
	console_sysfs_notify();
	return res;
}
EXPORT_SYMBOL(unregister_console);

/*
 * Some boot consoles access data that is in the init section and which will
 * be discarded after the initcalls have been run. To make sure that no code
 * will access this data, unregister the boot consoles in a late initcall.
 *
 * If for some reason, such as deferred probe or the driver being a loadable
 * module, the real console hasn't registered yet at this point, there will
 * be a brief interval in which no messages are logged to the console, which
 * makes it difficult to diagnose problems that occur during this time.
 *
 * To mitigate this problem somewhat, only unregister consoles whose memory
 * intersects with the init section. Note that code exists elsewhere to get
 * rid of the boot console as soon as the proper console shows up, so there
 * won't be side-effects from postponing the removal.
 */
static int __init printk_late_init(void)
{
	struct console *con;

	for_each_console(con) {
		if (!keep_bootcon && con->flags & CON_BOOT) {
			/*
			 * Make sure to unregister boot consoles whose data
			 * resides in the init section before the init section
			 * is discarded. Boot consoles whose data will stick
			 * around will automatically be unregistered when the
			 * proper console replaces them.
			 */
			if (init_section_intersects(con, sizeof(*con)))
				unregister_console(con);
		}
	}
	hotcpu_notifier(console_cpu_notify, 0);
	return 0;
}
late_initcall(printk_late_init);

#if defined CONFIG_PRINTK
/*
 * Prevent starting printk_kthread from start_kernel()->parse_args().
 * It's not possible at this stage. Instead, do it via the initcall
 * or a sysfs knob.
 */
static bool printk_kthread_can_run;

static int printk_kthread_func(void *data)
{
	while (1) {
		set_current_state(TASK_INTERRUPTIBLE);
		if (!printk_kthread_need_flush_console)
			schedule();

		__set_current_state(TASK_RUNNING);
		/*
		 * Avoid an infinite loop when console_unlock() cannot
		 * access consoles, e.g. because console_suspended is
		 * true. schedule(), someone else will print the messages
		 * from resume_console().
		 */
		printk_kthread_need_flush_console = false;

		console_lock();
		console_unlock();
	}

	return 0;
}

static int __init_printk_kthread(void)
{
	struct task_struct *thread;
	struct sched_param param = {
		.sched_priority = MAX_RT_PRIO - 1,
	};

	if (!printk_kthread_can_run || printk_sync || printk_kthread)
		return 0;

	thread = kthread_run(printk_kthread_func, NULL, "printk");
	if (IS_ERR(thread)) {
		pr_err("printk: unable to create printing thread\n");
		printk_sync = true;
		return PTR_ERR(thread);
	}

	sched_setscheduler(thread, SCHED_FIFO, &param);
	printk_kthread = thread;
	return 0;
}

static int printk_sync_set(const char *val, const struct kernel_param *kp)
{
	int ret;

	ret = param_set_bool(val, kp);
	if (ret)
		return ret;
	return __init_printk_kthread();
}

static const struct kernel_param_ops param_ops_printk_sync = {
	.set = printk_sync_set,
	.get = param_get_bool,
};

module_param_cb(synchronous, &param_ops_printk_sync, &printk_sync,
		S_IRUGO | S_IWUSR);
MODULE_PARM_DESC(synchronous, "make printing to console synchronous");

/*
 * Init async printk via late_initcall, after core/arch/etc.
 * initialization.
 */
static __init int init_printk_kthread(void)
{
	printk_kthread_can_run = true;
	return __init_printk_kthread();
}
late_initcall(init_printk_kthread);

/*
 * Delayed printk version, for scheduler-internal messages:
 */
#define PRINTK_PENDING_WAKEUP	0x01
#define PRINTK_PENDING_OUTPUT	0x02

static DEFINE_PER_CPU(int, printk_pending);

static void wake_up_klogd_work_func(struct irq_work *irq_work)
{
	int pending = __this_cpu_xchg(printk_pending, 0);

	if (pending & PRINTK_PENDING_OUTPUT) {
		if (can_printk_async()) {
			wake_up_process(printk_kthread);
		} else {
			/*
			 * If trylock fails, someone else is doing
			 * the printing
			 */
			if (console_trylock())
				console_unlock();
		}
	}

	if (pending & PRINTK_PENDING_WAKEUP)
		wake_up_interruptible(&log_wait);
}

static DEFINE_PER_CPU(struct irq_work, wake_up_klogd_work) = {
	.func = wake_up_klogd_work_func,
	.flags = IRQ_WORK_LAZY,
};

void wake_up_klogd(void)
{
	preempt_disable();
	if (waitqueue_active(&log_wait)) {
		this_cpu_or(printk_pending, PRINTK_PENDING_WAKEUP);
		irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
	}
	preempt_enable();
}

int printk_deferred(const char *fmt, ...)
{
	va_list args;
	int r;

	preempt_disable();
	va_start(args, fmt);
	r = vprintk_emit(0, LOGLEVEL_SCHED, NULL, 0, fmt, args);
	va_end(args);

	__this_cpu_or(printk_pending, PRINTK_PENDING_OUTPUT);
	irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
	preempt_enable();

	return r;
}

/*
 * printk rate limiting, lifted from the networking subsystem.
 *
 * This enforces a rate limit: not more than 10 kernel messages
 * every 5s to make a denial-of-service attack impossible.
 */
DEFINE_RATELIMIT_STATE(printk_ratelimit_state, 5 * HZ, 10);

int __printk_ratelimit(const char *func)
{
	return ___ratelimit(&printk_ratelimit_state, func);
}
EXPORT_SYMBOL(__printk_ratelimit);

/**
 * printk_timed_ratelimit - caller-controlled printk ratelimiting
 * @caller_jiffies: pointer to caller's state
 * @interval_msecs: minimum interval between prints
 *
 * printk_timed_ratelimit() returns true if more than @interval_msecs
 * milliseconds have elapsed since the last time printk_timed_ratelimit()
 * returned true.
 */
bool printk_timed_ratelimit(unsigned long *caller_jiffies,
			unsigned int interval_msecs)
{
	unsigned long elapsed = jiffies - *caller_jiffies;

	if (*caller_jiffies && elapsed <= msecs_to_jiffies(interval_msecs))
		return false;

	*caller_jiffies = jiffies;
	return true;
}
EXPORT_SYMBOL(printk_timed_ratelimit);

static DEFINE_SPINLOCK(dump_list_lock);
static LIST_HEAD(dump_list);

/**
 * kmsg_dump_register - register a kernel log dumper.
 * @dumper: pointer to the kmsg_dumper structure
 *
 * Adds a kernel log dumper to the system. The dump callback in the
 * structure will be called when the kernel oopses or panics and must be
 * set. Returns zero on success and %-EINVAL or %-EBUSY otherwise.
 */
int kmsg_dump_register(struct kmsg_dumper *dumper)
{
	unsigned long flags;
	int err = -EBUSY;

	/* The dump callback needs to be set */
	if (!dumper->dump)
		return -EINVAL;

	spin_lock_irqsave(&dump_list_lock, flags);
	/* Don't allow registering multiple times */
	if (!dumper->registered) {
		dumper->registered = 1;
		list_add_tail_rcu(&dumper->list, &dump_list);
		err = 0;
	}
	spin_unlock_irqrestore(&dump_list_lock, flags);

	return err;
}
EXPORT_SYMBOL_GPL(kmsg_dump_register);

/**
 * kmsg_dump_unregister - unregister a kmsg dumper.
 * @dumper: pointer to the kmsg_dumper structure
 *
 * Removes a dump device from the system. Returns zero on success and
 * %-EINVAL otherwise.
 */
int kmsg_dump_unregister(struct kmsg_dumper *dumper)
{
	unsigned long flags;
	int err = -EINVAL;

	spin_lock_irqsave(&dump_list_lock, flags);
	if (dumper->registered) {
		dumper->registered = 0;
		list_del_rcu(&dumper->list);
		err = 0;
	}
	spin_unlock_irqrestore(&dump_list_lock, flags);
	synchronize_rcu();

	return err;
}
EXPORT_SYMBOL_GPL(kmsg_dump_unregister);

static bool always_kmsg_dump;
module_param_named(always_kmsg_dump, always_kmsg_dump, bool, S_IRUGO | S_IWUSR);

/**
 * kmsg_dump - dump kernel log to kernel message dumpers.
 * @reason: the reason (oops, panic etc) for dumping
 *
 * Call each of the registered dumper's dump() callback, which can
 * retrieve the kmsg records with kmsg_dump_get_line() or
 * kmsg_dump_get_buffer().
 */
void kmsg_dump(enum kmsg_dump_reason reason)
{
	struct kmsg_dumper *dumper;
	unsigned long flags;

	if ((reason > KMSG_DUMP_OOPS) && !always_kmsg_dump)
		return;

	rcu_read_lock();
	list_for_each_entry_rcu(dumper, &dump_list, list) {
		if (dumper->max_reason && reason > dumper->max_reason)
			continue;

		/* initialize iterator with data about the stored records */
		dumper->active = true;

		raw_spin_lock_irqsave(&logbuf_lock, flags);
		dumper->cur_seq = clear_seq;
		dumper->cur_idx = clear_idx;
		dumper->next_seq = log_next_seq;
		dumper->next_idx = log_next_idx;
		raw_spin_unlock_irqrestore(&logbuf_lock, flags);

		/* invoke dumper which will iterate over records */
		dumper->dump(dumper, reason);

		/* reset iterator */
		dumper->active = false;
	}
	rcu_read_unlock();
}

/**
 * kmsg_dump_get_line_nolock - retrieve one kmsg log line (unlocked version)
 * @dumper: registered kmsg dumper
 * @syslog: include the "<4>" prefixes
 * @line: buffer to copy the line to
 * @size: maximum size of the buffer
 * @len: length of line placed into buffer
 *
 * Start at the beginning of the kmsg buffer, with the oldest kmsg
 * record, and copy one record into the provided buffer.
 *
 * Consecutive calls will return the next available record moving
 * towards the end of the buffer with the youngest messages.
 *
 * A return value of FALSE indicates that there are no more records to
 * read.
 *
 * The function is similar to kmsg_dump_get_line(), but grabs no locks.
 */
bool kmsg_dump_get_line_nolock(struct kmsg_dumper *dumper, bool syslog,
			       char *line, size_t size, size_t *len)
{
	struct printk_log *msg;
	size_t l = 0;
	bool ret = false;

	if (!dumper->active)
		goto out;

	if (dumper->cur_seq < log_first_seq) {
		/* messages are gone, move to first available one */
		dumper->cur_seq = log_first_seq;
		dumper->cur_idx = log_first_idx;
	}

	/* last entry */
	if (dumper->cur_seq >= log_next_seq)
		goto out;

	msg = log_from_idx(dumper->cur_idx);
	l = msg_print_text(msg, 0, syslog, line, size);

	dumper->cur_idx = log_next(dumper->cur_idx);
	dumper->cur_seq++;
	ret = true;
out:
	if (len)
		*len = l;
	return ret;
}

/**
 * kmsg_dump_get_line - retrieve one kmsg log line
 * @dumper: registered kmsg dumper
 * @syslog: include the "<4>" prefixes
 * @line: buffer to copy the line to
 * @size: maximum size of the buffer
 * @len: length of line placed into buffer
 *
 * Start at the beginning of the kmsg buffer, with the oldest kmsg
 * record, and copy one record into the provided buffer.
 *
 * Consecutive calls will return the next available record moving
 * towards the end of the buffer with the youngest messages.
 *
 * A return value of FALSE indicates that there are no more records to
 * read.
 */
bool kmsg_dump_get_line(struct kmsg_dumper *dumper, bool syslog,
			char *line, size_t size, size_t *len)
{
	unsigned long flags;
	bool ret;

	raw_spin_lock_irqsave(&logbuf_lock, flags);
	ret = kmsg_dump_get_line_nolock(dumper, syslog, line, size, len);
	raw_spin_unlock_irqrestore(&logbuf_lock, flags);

	return ret;
}
EXPORT_SYMBOL_GPL(kmsg_dump_get_line);

/**
 * kmsg_dump_get_buffer - copy kmsg log lines
 * @dumper: registered kmsg dumper
 * @syslog: include the "<4>" prefixes
 * @buf: buffer to copy the line to
 * @size: maximum size of the buffer
 * @len: length of line placed into buffer
 *
 * Start at the end of the kmsg buffer and fill the provided buffer
 * with as many of the the *youngest* kmsg records that fit into it.
 * If the buffer is large enough, all available kmsg records will be
 * copied with a single call.
 *
 * Consecutive calls will fill the buffer with the next block of
 * available older records, not including the earlier retrieved ones.
 *
 * A return value of FALSE indicates that there are no more records to
 * read.
 */
bool kmsg_dump_get_buffer(struct kmsg_dumper *dumper, bool syslog,
			  char *buf, size_t size, size_t *len)
{
	unsigned long flags;
	u64 seq;
	u32 idx;
	u64 next_seq;
	u32 next_idx;
	enum log_flags prev;
	size_t l = 0;
	bool ret = false;

	if (!dumper->active)
		goto out;

	raw_spin_lock_irqsave(&logbuf_lock, flags);
	if (dumper->cur_seq < log_first_seq) {
		/* messages are gone, move to first available one */
		dumper->cur_seq = log_first_seq;
		dumper->cur_idx = log_first_idx;
	}

	/* last entry */
	if (dumper->cur_seq >= dumper->next_seq) {
		raw_spin_unlock_irqrestore(&logbuf_lock, flags);
		goto out;
	}

	/* calculate length of entire buffer */
	seq = dumper->cur_seq;
	idx = dumper->cur_idx;
	prev = 0;
	while (seq < dumper->next_seq) {
		struct printk_log *msg = log_from_idx(idx);

		l += msg_print_text(msg, prev, true, NULL, 0);
		idx = log_next(idx);
		seq++;
		prev = msg->flags;
	}

	/* move first record forward until length fits into the buffer */
	seq = dumper->cur_seq;
	idx = dumper->cur_idx;
	prev = 0;
	while (l > size && seq < dumper->next_seq) {
		struct printk_log *msg = log_from_idx(idx);

		l -= msg_print_text(msg, prev, true, NULL, 0);
		idx = log_next(idx);
		seq++;
		prev = msg->flags;
	}

	/* last message in next interation */
	next_seq = seq;
	next_idx = idx;

	l = 0;
	while (seq < dumper->next_seq) {
		struct printk_log *msg = log_from_idx(idx);

		l += msg_print_text(msg, prev, syslog, buf + l, size - l);
		idx = log_next(idx);
		seq++;
		prev = msg->flags;
	}

	dumper->next_seq = next_seq;
	dumper->next_idx = next_idx;
	ret = true;
	raw_spin_unlock_irqrestore(&logbuf_lock, flags);
out:
	if (len)
		*len = l;
	return ret;
}
EXPORT_SYMBOL_GPL(kmsg_dump_get_buffer);

/**
 * kmsg_dump_rewind_nolock - reset the interator (unlocked version)
 * @dumper: registered kmsg dumper
 *
 * Reset the dumper's iterator so that kmsg_dump_get_line() and
 * kmsg_dump_get_buffer() can be called again and used multiple
 * times within the same dumper.dump() callback.
 *
 * The function is similar to kmsg_dump_rewind(), but grabs no locks.
 */
void kmsg_dump_rewind_nolock(struct kmsg_dumper *dumper)
{
	dumper->cur_seq = clear_seq;
	dumper->cur_idx = clear_idx;
	dumper->next_seq = log_next_seq;
	dumper->next_idx = log_next_idx;
}

/**
 * kmsg_dump_rewind - reset the interator
 * @dumper: registered kmsg dumper
 *
 * Reset the dumper's iterator so that kmsg_dump_get_line() and
 * kmsg_dump_get_buffer() can be called again and used multiple
 * times within the same dumper.dump() callback.
 */
void kmsg_dump_rewind(struct kmsg_dumper *dumper)
{
	unsigned long flags;

	raw_spin_lock_irqsave(&logbuf_lock, flags);
	kmsg_dump_rewind_nolock(dumper);
	raw_spin_unlock_irqrestore(&logbuf_lock, flags);
}
EXPORT_SYMBOL_GPL(kmsg_dump_rewind);

static char dump_stack_arch_desc_str[128];

/**
 * dump_stack_set_arch_desc - set arch-specific str to show with task dumps
 * @fmt: printf-style format string
 * @...: arguments for the format string
 *
 * The configured string will be printed right after utsname during task
 * dumps.  Usually used to add arch-specific system identifiers.  If an
 * arch wants to make use of such an ID string, it should initialize this
 * as soon as possible during boot.
 */
void __init dump_stack_set_arch_desc(const char *fmt, ...)
{
	va_list args;

	va_start(args, fmt);
	vsnprintf(dump_stack_arch_desc_str, sizeof(dump_stack_arch_desc_str),
		  fmt, args);
	va_end(args);
}

/**
 * dump_stack_print_info - print generic debug info for dump_stack()
 * @log_lvl: log level
 *
 * Arch-specific dump_stack() implementations can use this function to
 * print out the same debug information as the generic dump_stack().
 */
void dump_stack_print_info(const char *log_lvl)
{
	printk("%sCPU: %d PID: %d Comm: %.20s %s %s %.*s\n",
	       log_lvl, raw_smp_processor_id(), current->pid, current->comm,
	       print_tainted(), init_utsname()->release,
	       (int)strcspn(init_utsname()->version, " "),
	       init_utsname()->version);

	if (dump_stack_arch_desc_str[0] != '\0')
		printk("%sHardware name: %s\n",
		       log_lvl, dump_stack_arch_desc_str);

	print_worker_info(log_lvl, current);
}

/**
 * show_regs_print_info - print generic debug info for show_regs()
 * @log_lvl: log level
 *
 * show_regs() implementations can use this function to print out generic
 * debug information.
 */
void show_regs_print_info(const char *log_lvl)
{
	dump_stack_print_info(log_lvl);

	printk("%stask: %p ti: %p task.ti: %p\n",
	       log_lvl, current, current_thread_info(),
	       task_thread_info(current));
}

#endif

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

[Viresh Kumar]

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

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

So I tried it cleanly without any local hacks using:

echo core > /sys/power/pm_test

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

FWIW, I also tried this hacky thing:

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


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

This FIXES the hangs for me :)


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

-- 
viresh

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

[Rafael J. Wysocki]

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

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

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

[Viresh Kumar]

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

Thanks.

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

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

-- 
viresh

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

[Viresh Kumar]

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

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

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

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

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

        raw_spin_lock_irqsave(&p->pi_lock, flags);

I will explain how:

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

        WARN_ON(timekeeping_suspended);

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

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

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

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

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

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

Maybe something more in can_print_async() routine, like:

only-one-cpu-online + irqs_disabled()

or whatever.

-- 
viresh

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

[Viresh Kumar]

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

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

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

-- 
viresh

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

[Sergey Senozhatsky]

Cc Petr Mladek.

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

good find!

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

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

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

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

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

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

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

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

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


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

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

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

printk() has many issues.

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

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

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

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

								IRQ
								printk()

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

						  console_sem_up()
						  return

with async printk here we can offload printing from IRQ.

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


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

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


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

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

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

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

[Sergey Senozhatsky]

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

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


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

	-ss

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

[Rafael J. Wysocki]

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

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

Thanks,
Rafael

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

[Sergey Senozhatsky]

Hello Rafael,

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

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

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

am I missing something?

	-ss

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

[Rafael J. Wysocki]

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

Ah OK.  That should work for hibernation too.

> am I missing something?

No, I got confused for some reason.

Thanks,
Rafael

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

[Viresh Kumar]

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

I see.

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

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

:)

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

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

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

Right.

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

Right.

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

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

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

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

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

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

-- 
viresh

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

[Rafael J. Wysocki]

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

[cut]

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

How can it hog that CPU, exactly?

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

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

Are all of those messages printed actually useful?

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

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

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

Thanks,
Rafael

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

[Viresh Kumar]

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

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

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

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

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

> Are all of those messages printed actually useful?

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

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

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

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

-- 
viresh

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

[Greg Kroah-Hartman]

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

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

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

thanks,

greg k-h

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

[Sergey Senozhatsky]

Hello,

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

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

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

a silly question -- can we suspend consoles later?

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

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

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

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

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

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

	-ss

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

[Rafael J. Wysocki]

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

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

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

[Sergey Senozhatsky]

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

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

thanks for your late night reply!

	-ss

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

[Jan Kara]

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

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

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

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

So there are IMHO two issues here worth looking at:

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

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

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

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

								Honza

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

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

[Rafael J. Wysocki]

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

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

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

Thanks,
Rafael

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

[Sergey Senozhatsky]

Hello Jan,

On (07/14/16 16:12), Jan Kara wrote:
[..]
> > *** a printk() call from here will kill the system. either it will
> > recurse printk(), or spin forever in 'nested' printk() on one of
> > the already taken spin locks.
[..]
> And with sync printk the above deadlock doesn't trigger only by chance - if
> there happened to be a waiter on console_sem while we suspend, the same
> deadlock would trigger because up(&console_sem) will try to wake him up and
> the warning in timekeeping code will cause recursive printk.
> 
> So I think your patch doesn't really address the real issue - it only
> works around the particular WARN_ON(timekeeping_enabled) warning but if
> there was a different warning in timekeeping code which would trigger, it
> has a potential for causing recursive printk deadlock (and indeed we had
> such issues previously - see e.g. 504d58745c9c "timer: Fix lock inversion
> between hrtimer_bases.lock and scheduler locks").

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

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



and cpu_down() in printk does

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

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

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

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

	-ss

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

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

[Jan Kara]

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

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

								Honza

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

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

[Rafael J. Wysocki]

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

Fair enough.

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

Thanks,
Rafael

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

[Jan Kara]

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

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

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

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

[Jan Kara]

On Thu 14-07-16 23:34:50, Sergey Senozhatsky wrote:
> Hello Jan,
> 
> On (07/14/16 16:12), Jan Kara wrote:
> [..]
> > > *** a printk() call from here will kill the system. either it will
> > > recurse printk(), or spin forever in 'nested' printk() on one of
> > > the already taken spin locks.
> [..]
> > And with sync printk the above deadlock doesn't trigger only by chance - if
> > there happened to be a waiter on console_sem while we suspend, the same
> > deadlock would trigger because up(&console_sem) will try to wake him up and
> > the warning in timekeeping code will cause recursive printk.
> > 
> > So I think your patch doesn't really address the real issue - it only
> > works around the particular WARN_ON(timekeeping_enabled) warning but if
> > there was a different warning in timekeeping code which would trigger, it
> > has a potential for causing recursive printk deadlock (and indeed we had
> > such issues previously - see e.g. 504d58745c9c "timer: Fix lock inversion
> > between hrtimer_bases.lock and scheduler locks").
> 
> we switch to sync printk in suspend_console(), that is happening
> long before we start bringing cpu downs
> 
> suspend_devices_and_enter()
> 	suspend_console()
> 	...
> 	suspend_enter()
> 		...
> 		dpm_suspend_late
> 		...
> 		disable_nonboot_cpus
> 
> 
> 
> and cpu_down() in printk does
> 
> static int console_cpu_notify(struct notifier_block *self,
> 	unsigned long action, void *hcpu)
> {
> 	switch (action) {
> 	case CPU_ONLINE:
> 	case CPU_DEAD:
> 	case CPU_DOWN_FAILED:
> 	case CPU_UP_CANCELED:
> 		console_lock();
> 		console_unlock();
> 	}
> 	return NOTIFY_OK;
> }
> 
> so I think this console_lock() sort of guarantees that there should be
> no sleeping tasks in console semaphore wait list. or am I missing something?

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

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

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

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

[Viresh Kumar]

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

Hmm...

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

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

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

-- 
viresh

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

[Viresh Kumar]

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

That option is enabled only for testing though :)

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

I actually need to test it out as well :)

-- 
viresh

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

[Viresh Kumar]

On 14-07-16, 16:12, Jan Kara wrote:
> Exactly. Calling printk() from certain parts of the kernel (like scheduler
> code or timer code) has been always unsafe because printk itself uses these
> parts and so it can lead to deadlocks. That's why printk_deffered() has
> been introduced as you mention below.
> 
> And with sync printk the above deadlock doesn't trigger only by chance - if
> there happened to be a waiter on console_sem while we suspend, the same
> deadlock would trigger because up(&console_sem) will try to wake him up and
> the warning in timekeeping code will cause recursive printk.
> 
> So I think your patch doesn't really address the real issue - it only
> works around the particular WARN_ON(timekeeping_enabled) warning but if
> there was a different warning in timekeeping code which would trigger, it
> has a potential for causing recursive printk deadlock (and indeed we had
> such issues previously - see e.g. 504d58745c9c "timer: Fix lock inversion
> between hrtimer_bases.lock and scheduler locks").
> 
> So there are IMHO two issues here worth looking at:
> 
> 1) I didn't find how a wakeup would would lead to calling to ktime_get() in
> the current upstream kernel or even current RT kernel. Maybe this is a
> problem specific to the 3.10 kernel you are using? If yes, we don't have to
> do anything for current upstream AFAIU.

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

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

> If I just missed how wakeup can call into ktime_get() in current upstream,
> there is another question:
> 
> 2) Is it OK that printk calls wakeup so late during suspend?

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

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

> I believe it
> is but I'm neither scheduler nor suspend expert. If it is OK, and wakeup
> can lead to ktime_get() in current upstream, then this contradicts the
> check WARN_ON(timekeeping_suspended) in ktime_get() and something is wrong.
> 
> Adding Thomas to CC as timer / RT expert...

Thanks.

-- 
viresh

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

[Viresh Kumar]

On 14-07-16, 16:55, Jan Kara wrote:
> Agree on that - but that seems to be a problem of a particular wakeup
> implementation of the 3.10 kernel Viresh is using, not a problem of the
> upstream kernel.

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

-- 
viresh

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

[Viresh Kumar]

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

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

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

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

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

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

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

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

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

-- 
viresh

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

[Sergey Senozhatsky]

Hello,

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

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

something like

CPU0						CPU1

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

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

	call_console_drivers()

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

	-ss


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

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

[Viresh Kumar]

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

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

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

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

Hmm, I am not sure of it yet.

-- 
viresh

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

[Jan Kara]

On Thu 14-07-16 15:12:51, Viresh Kumar wrote:
> On 14-07-16, 16:12, Jan Kara wrote:
> > Exactly. Calling printk() from certain parts of the kernel (like scheduler
> > code or timer code) has been always unsafe because printk itself uses these
> > parts and so it can lead to deadlocks. That's why printk_deffered() has
> > been introduced as you mention below.
> > 
> > And with sync printk the above deadlock doesn't trigger only by chance - if
> > there happened to be a waiter on console_sem while we suspend, the same
> > deadlock would trigger because up(&console_sem) will try to wake him up and
> > the warning in timekeeping code will cause recursive printk.
> > 
> > So I think your patch doesn't really address the real issue - it only
> > works around the particular WARN_ON(timekeeping_enabled) warning but if
> > there was a different warning in timekeeping code which would trigger, it
> > has a potential for causing recursive printk deadlock (and indeed we had
> > such issues previously - see e.g. 504d58745c9c "timer: Fix lock inversion
> > between hrtimer_bases.lock and scheduler locks").
> > 
> > So there are IMHO two issues here worth looking at:
> > 
> > 1) I didn't find how a wakeup would would lead to calling to ktime_get() in
> > the current upstream kernel or even current RT kernel. Maybe this is a
> > problem specific to the 3.10 kernel you are using? If yes, we don't have to
> > do anything for current upstream AFAIU.
> 
> I haven't checked that earlier, but I see the path in both 3.10 and mainline.
> 
> vprintk_emit
>  -> wake_up_process
>   -> try_to_wake_up
>    -> ttwu_queue
>     -> ttwu_do_activate
>      -> ttwu_activate
>       -> activate_task
>        -> enqueue_task (sched/core.c)
>         -> enqueue_task_rt (rt.c)
>          -> enqueue_rt_entity
>           -> __enqueue_rt_entity
>            -> inc_rt_tasks
>             -> inc_rt_group
>              -> start_rt_bandwidth
>               -> start_bandwidth_timer
>                -> __hrtimer_start_range_ns
>                 -> ktime_get()

Yeah, you are right.

> > If I just missed how wakeup can call into ktime_get() in current upstream,
> > there is another question:
> > 
> > 2) Is it OK that printk calls wakeup so late during suspend?
> 
> To clarify again to everybody, we are talking about the place where all
> non-boot CPUs are already hot-unplugged and the last running one has
> disabled interrupts.
> 
> I believe that we can't do migration at all now, right? What will we get by
> calling wake_up_process() now anyway ?

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

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

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

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

[Rafael J. Wysocki]

On Monday, July 18, 2016 01:01:34 PM Jan Kara wrote:
> On Thu 14-07-16 15:12:51, Viresh Kumar wrote:
> > On 14-07-16, 16:12, Jan Kara wrote:
> > > Exactly. Calling printk() from certain parts of the kernel (like scheduler
> > > code or timer code) has been always unsafe because printk itself uses these
> > > parts and so it can lead to deadlocks. That's why printk_deffered() has
> > > been introduced as you mention below.
> > > 
> > > And with sync printk the above deadlock doesn't trigger only by chance - if
> > > there happened to be a waiter on console_sem while we suspend, the same
> > > deadlock would trigger because up(&console_sem) will try to wake him up and
> > > the warning in timekeeping code will cause recursive printk.
> > > 
> > > So I think your patch doesn't really address the real issue - it only
> > > works around the particular WARN_ON(timekeeping_enabled) warning but if
> > > there was a different warning in timekeeping code which would trigger, it
> > > has a potential for causing recursive printk deadlock (and indeed we had
> > > such issues previously - see e.g. 504d58745c9c "timer: Fix lock inversion
> > > between hrtimer_bases.lock and scheduler locks").
> > > 
> > > So there are IMHO two issues here worth looking at:
> > > 
> > > 1) I didn't find how a wakeup would would lead to calling to ktime_get() in
> > > the current upstream kernel or even current RT kernel. Maybe this is a
> > > problem specific to the 3.10 kernel you are using? If yes, we don't have to
> > > do anything for current upstream AFAIU.
> > 
> > I haven't checked that earlier, but I see the path in both 3.10 and mainline.
> > 
> > vprintk_emit
> >  -> wake_up_process
> >   -> try_to_wake_up
> >    -> ttwu_queue
> >     -> ttwu_do_activate
> >      -> ttwu_activate
> >       -> activate_task
> >        -> enqueue_task (sched/core.c)
> >         -> enqueue_task_rt (rt.c)
> >          -> enqueue_rt_entity
> >           -> __enqueue_rt_entity
> >            -> inc_rt_tasks
> >             -> inc_rt_group
> >              -> start_rt_bandwidth
> >               -> start_bandwidth_timer
> >                -> __hrtimer_start_range_ns
> >                 -> ktime_get()
> 
> Yeah, you are right.
> 
> > > If I just missed how wakeup can call into ktime_get() in current upstream,
> > > there is another question:
> > > 
> > > 2) Is it OK that printk calls wakeup so late during suspend?
> > 
> > To clarify again to everybody, we are talking about the place where all
> > non-boot CPUs are already hot-unplugged and the last running one has
> > disabled interrupts.
> > 
> > I believe that we can't do migration at all now, right? What will we get by
> > calling wake_up_process() now anyway ?
> 
> As I already wrote to Rafael, wake_up_process() will change the process
> state to TASK_RUNNING so that it can run after we resume from suspend.
> 
> But seeing that the same problem is in upstream I guess what Sergey did
> makes more sense if it works for you. If Sergey's fix does not work for you
> due to too many messages being printed during device suspend, then we will
> have to try something else...

Which is exactly my point. :-)

Thanks,
Rafael

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

[Viresh Kumar]

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

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

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

-- 
viresh

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

[Sergey Senozhatsky]

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

Thanks a lot!
will refresh the series next week.

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

	-ss