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

Groups > linux.kernel > #1461047 > unrolled thread

Re: [PATCH v10 1/2] printk: Make printk() completely async

Back to article view | Back to linux.kernel

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

Contents

  Re: [PATCH v10 1/2] printk: Make printk() completely async Petr Mladek <pmladek@suse.com> - 2016-08-12 11:50 +0200
    Re: [PATCH v10 1/2] printk: Make printk() completely async Vladislav Levenetz <vlevenetz@mm-sol.com> - 2016-08-15 16:40 +0200
      Re: [PATCH v10 1/2] printk: Make printk() completely async Petr Mladek <pmladek@suse.com> - 2016-08-16 11:10 +0200
    Re: [PATCH v10 1/2] printk: Make printk() completely async Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-08-18 04:30 +0200
      Re: [PATCH v10 1/2] printk: Make printk() completely async Petr Mladek <pmladek@suse.com> - 2016-08-18 11:40 +0200
        Re: [PATCH v10 1/2] printk: Make printk() completely async Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-08-18 12:00 +0200
          Re: [PATCH v10 1/2] printk: Make printk() completely async Petr Mladek <pmladek@suse.com> - 2016-08-18 13:00 +0200
            Re: [PATCH v10 1/2] printk: Make printk() completely async Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-08-19 08:40 +0200
              Re: [PATCH v10 1/2] printk: Make printk() completely async Petr Mladek <pmladek@suse.com> - 2016-08-19 12:00 +0200
                Re: [PATCH v10 1/2] printk: Make printk() completely async Jan Kara <jack@suse.cz> - 2016-08-19 21:10 +0200
                  Re: [PATCH v10 1/2] printk: Make printk() completely async Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2016-08-20 07:30 +0200
                    Re: [PATCH v10 1/2] printk: Make printk() completely async Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-08-22 06:20 +0200
                      Re: [PATCH v10 1/2] printk: Make printk() completely async Petr Mladek <pmladek@suse.com> - 2016-08-23 14:20 +0200
                        Re: [PATCH v10 1/2] printk: Make printk() completely async Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-08-24 03:40 +0200
                    Re: [PATCH v10 1/2] printk: Make printk() completely async Petr Mladek <pmladek@suse.com> - 2016-08-23 15:10 +0200
                  Re: [PATCH v10 1/2] printk: Make printk() completely async Petr Mladek <pmladek@suse.com> - 2016-08-23 15:50 +0200

#1461047 — Re: [PATCH v10 1/2] printk: Make printk() completely async

On Wed 2016-08-10 14:17:55, Viresh Kumar wrote:
> +Vladi/Greg,
> 
> On Wed, Apr 6, 2016 at 1:27 AM, Jan Kara <jack@suse.cz> wrote:
> > On Mon 04-04-16 15:51:49, Andrew Morton wrote:
> 
> >> > +static int __init init_printk_kthread(void)
> >> > +{
> >> > +   struct task_struct *thread;
> >> > +
> >> > +   if (printk_sync)
> >> > +           return 0;
> >> > +
> >> > +   thread = kthread_run(printk_kthread_func, NULL, "printk");
> >>
> >> This gets normal scheduling policy, so a spinning userspace SCHED_FIFO
> >> task will block printk for ever.  This seems bad.
> >
> > I have to research this a bit but won't the SCHED_FIFO task that has
> > potentially unbounded amount of work lockup the CPU even though it does
> > occasional cond_resched()?
> 
> We are facing complete hogs because of the printk thread being a SCHED_FIFO
> task and have this patch to fix it up for now.
> 
> Author: Vladislav Levenetz <vblagoev@mm-sol.com>
> Date:   Wed Aug 10 13:58:00 2016 -0700
> 
>     SW-7786: printk: Lower the priority of printk thread
> 
>     Flooding the console (with a test module) in a tight loop indefinitely
>     makes android user interface very sluggish. Opening YouTube app and the
>     device hangs and becomes even more unresponsive to the point it
>     completely hangs.
> 
>     The asynchronous printk thread is a SCHED FIFO thread with priority
>     MAX_RT_PRIO - 1. If we create it as a simple thread (i.e. no SCHED FIFO)
>     instead, we observe much better performance using the same printk flood
>     test. We don't even notice any kind of sluggishness during device usage.
>     We can play a YouTube clip smoothly and use the device normally in
>     general.  The kernel log looks fine as well, as the flood of messages
>     continue normally.
> 
>     Signed-off-by: Vladislav Levenetz <vblagoev@mm-sol.com>
>     Signed-off-by: Viresh Kumar <viresh.kumar@linaro.org>
> ---
>  kernel/printk/printk.c | 4 ----
>  1 file changed, 4 deletions(-)
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index c32872872cb6..ad5b30e5e6d9 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -2856,9 +2856,6 @@ static int printk_kthread_func(void *data)
>  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;
> @@ -2870,7 +2867,6 @@ static int __init_printk_kthread(void)
>                 return PTR_ERR(thread);
>         }
> 
> -       sched_setscheduler(thread, SCHED_FIFO, &param);
>         printk_kthread = thread;
>         return 0;
>  }

IMHO, this is fine. We force the synchronous mode in critical
situations anyway.

But I was curious if we could hit a printk from the wake_up_process().
The change above causes using the fair scheduler and there is
the following call chain [*]

  vprintk_emit()
  -> wake_up_process()
   -> try_to_wake_up()
    -> ttwu_queue()
     -> ttwu_do_activate()
      -> ttwu_activate()
       -> activate_task()
	-> enqueue_task()
	 -> enqueue_task_fair()	    via p->sched_class->enqueue_task
	  -> cfs_rq_of()
	   -> task_of()
	    -> WARN_ON_ONCE(!entity_is_task(se))

We should never trigger this because printk_kthread is a task.
But what if the date gets inconsistent?

Then there is the following chain:

  vprintk_emit()
  -> wake_up_process()
   -> try_to_wake_up()
    -> ttwu_queue()
     -> ttwu_do_activate()
      -> ttwu_activate()
       -> activate_task()
	-> enqueue_task()
	 -> enqueue_task_fair()	    via p->sched_class->enqueue_task
	  ->hrtick_update()
	   -> hrtick_start_fair()
	    -> WARN_ON(task_rq(p) != rq)

This looks like another paranoid consistency check that might be
triggered when the scheduler gets messed.

I see few possible solutions:

1. Replace the WARN_ONs by printk_deferred().

   This is the usual solution but it would make debugging less convenient.


2. Force synchronous printk inside WARN()/BUG() macros.

   This would make sense even from other reasons. These are printed
   when the system is in a strange state. There is no guarantee that
   the printk_kthread will get scheduled.


3. Force printk_deferred() inside WARN()/BUG() macros via the per-CPU
   printk_func.

   It might be elegant. But we do not want this outside the scheduler
   code. Therefore we would need special variants of  WARN_*_SCHED()
   BUG_*_SCHED() macros.


I personally prefer the 2nd solution. What do you think about it,
please?


Best Regards,
Petr

[toc] | [next] | [standalone]

#1462829

On 08/12/2016 12:44 PM, Petr Mladek wrote:
> On Wed 2016-08-10 14:17:55, Viresh Kumar wrote:
>> +Vladi/Greg,
>>
>> On Wed, Apr 6, 2016 at 1:27 AM, Jan Kara <jack@suse.cz> wrote:
>>> On Mon 04-04-16 15:51:49, Andrew Morton wrote:
>>>>> +static int __init init_printk_kthread(void)
>>>>> +{
>>>>> +   struct task_struct *thread;
>>>>> +
>>>>> +   if (printk_sync)
>>>>> +           return 0;
>>>>> +
>>>>> +   thread = kthread_run(printk_kthread_func, NULL, "printk");
>>>> This gets normal scheduling policy, so a spinning userspace SCHED_FIFO
>>>> task will block printk for ever.  This seems bad.
>>> I have to research this a bit but won't the SCHED_FIFO task that has
>>> potentially unbounded amount of work lockup the CPU even though it does
>>> occasional cond_resched()?
>> We are facing complete hogs because of the printk thread being a SCHED_FIFO
>> task and have this patch to fix it up for now.
>>
>> Author: Vladislav Levenetz <vblagoev@mm-sol.com>
>> Date:   Wed Aug 10 13:58:00 2016 -0700
>>
>>      SW-7786: printk: Lower the priority of printk thread
>>
>>      Flooding the console (with a test module) in a tight loop indefinitely
>>      makes android user interface very sluggish. Opening YouTube app and the
>>      device hangs and becomes even more unresponsive to the point it
>>      completely hangs.
>>
>>      The asynchronous printk thread is a SCHED FIFO thread with priority
>>      MAX_RT_PRIO - 1. If we create it as a simple thread (i.e. no SCHED FIFO)
>>      instead, we observe much better performance using the same printk flood
>>      test. We don't even notice any kind of sluggishness during device usage.
>>      We can play a YouTube clip smoothly and use the device normally in
>>      general.  The kernel log looks fine as well, as the flood of messages
>>      continue normally.
>>
>>      Signed-off-by: Vladislav Levenetz <vblagoev@mm-sol.com>
>>      Signed-off-by: Viresh Kumar <viresh.kumar@linaro.org>
>> ---
>>   kernel/printk/printk.c | 4 ----
>>   1 file changed, 4 deletions(-)
>>
>> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
>> index c32872872cb6..ad5b30e5e6d9 100644
>> --- a/kernel/printk/printk.c
>> +++ b/kernel/printk/printk.c
>> @@ -2856,9 +2856,6 @@ static int printk_kthread_func(void *data)
>>   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;
>> @@ -2870,7 +2867,6 @@ static int __init_printk_kthread(void)
>>                  return PTR_ERR(thread);
>>          }
>>
>> -       sched_setscheduler(thread, SCHED_FIFO, &param);
>>          printk_kthread = thread;
>>          return 0;
>>   }
> IMHO, this is fine. We force the synchronous mode in critical
> situations anyway.
>
> But I was curious if we could hit a printk from the wake_up_process().
> The change above causes using the fair scheduler and there is
> the following call chain [*]
>
>    vprintk_emit()
>    -> wake_up_process()
>     -> try_to_wake_up()
>      -> ttwu_queue()
>       -> ttwu_do_activate()
>        -> ttwu_activate()
>         -> activate_task()
> 	-> enqueue_task()
> 	 -> enqueue_task_fair()	    via p->sched_class->enqueue_task
> 	  -> cfs_rq_of()
> 	   -> task_of()
> 	    -> WARN_ON_ONCE(!entity_is_task(se))
>
> We should never trigger this because printk_kthread is a task.
> But what if the date gets inconsistent?
>
> Then there is the following chain:
>
>    vprintk_emit()
>    -> wake_up_process()
>     -> try_to_wake_up()
>      -> ttwu_queue()
>       -> ttwu_do_activate()
>        -> ttwu_activate()
>         -> activate_task()
> 	-> enqueue_task()
> 	 -> enqueue_task_fair()	    via p->sched_class->enqueue_task
> 	  ->hrtick_update()
> 	   -> hrtick_start_fair()
> 	    -> WARN_ON(task_rq(p) != rq)
>
> This looks like another paranoid consistency check that might be
> triggered when the scheduler gets messed.
>
> I see few possible solutions:
>
> 1. Replace the WARN_ONs by printk_deferred().
>
>     This is the usual solution but it would make debugging less convenient.
>
>
> 2. Force synchronous printk inside WARN()/BUG() macros.
>
>     This would make sense even from other reasons. These are printed
>     when the system is in a strange state. There is no guarantee that
>     the printk_kthread will get scheduled.
>
>
> 3. Force printk_deferred() inside WARN()/BUG() macros via the per-CPU
>     printk_func.
>
>     It might be elegant. But we do not want this outside the scheduler
>     code. Therefore we would need special variants of  WARN_*_SCHED()
>     BUG_*_SCHED() macros.
>
>
> I personally prefer the 2nd solution. What do you think about it,
> please?
>
>
> Best Regards,
> Petr

Hi Petr,

Sorry with for the late reply.

Hitting a WARN()/BUG() from wake_up calls will lead to a deadlock if 
only a single CPU is running.
We already had such a situation with system suspend. During a specific 
test on our device sometimes we hit a WARN from the time keeping core. 
(Cannot recall which one exactly. Viresh have it) from a printk wake_up 
path during system suspend and with already only one CPU running.
So we were forced to make printing synchronous in the suspend path prior 
disabling all non-boot cpu's.

Your solution number 2) sounds reasonable to me.

I'm wondering if we could hit a WARN()/BUG() somewhere from the fair 
scheduler like the example you made for the RT sched?

Thanks.

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

#1463567

On Mon 2016-08-15 17:26:50, Vladislav Levenetz wrote:
> On 08/12/2016 12:44 PM, Petr Mladek wrote:
> >But I was curious if we could hit a printk from the wake_up_process().
> >The change above causes using the fair scheduler and there is
> >the following call chain [*]
> >
> >   vprintk_emit()
> >   -> wake_up_process()
> >    -> try_to_wake_up()
> >     -> ttwu_queue()
> >      -> ttwu_do_activate()
> >       -> ttwu_activate()
> >        -> activate_task()
> >	-> enqueue_task()
> >	 -> enqueue_task_fair()	    via p->sched_class->enqueue_task
> >	  -> cfs_rq_of()
> >	   -> task_of()
> >	    -> WARN_ON_ONCE(!entity_is_task(se))
> >
> >We should never trigger this because printk_kthread is a task.
> >But what if the date gets inconsistent?
> >
> >Then there is the following chain:
> >
> >   vprintk_emit()
> >   -> wake_up_process()
> >    -> try_to_wake_up()
> >     -> ttwu_queue()
> >      -> ttwu_do_activate()
> >       -> ttwu_activate()
> >        -> activate_task()
> >	-> enqueue_task()
> >	 -> enqueue_task_fair()	    via p->sched_class->enqueue_task
> >	  ->hrtick_update()
> >	   -> hrtick_start_fair()
> >	    -> WARN_ON(task_rq(p) != rq)
> >
> >This looks like another paranoid consistency check that might be
> >triggered when the scheduler gets messed.
> >
> >I see few possible solutions:
> >
> >1. Replace the WARN_ONs by printk_deferred().
> >
> >    This is the usual solution but it would make debugging less convenient.
> >
> >
> >2. Force synchronous printk inside WARN()/BUG() macros.
> >
> >    This would make sense even from other reasons. These are printed
> >    when the system is in a strange state. There is no guarantee that
> >    the printk_kthread will get scheduled.
> >
> >
> >3. Force printk_deferred() inside WARN()/BUG() macros via the per-CPU
> >    printk_func.
> >
> >    It might be elegant. But we do not want this outside the scheduler
> >    code. Therefore we would need special variants of  WARN_*_SCHED()
> >    BUG_*_SCHED() macros.
> >
> >
> >I personally prefer the 2nd solution. What do you think about it,
> >please?
> >
> >
> >Best Regards,
> >Petr
> 
> Hi Petr,
> 
> Sorry with for the late reply.

No problem.

> Hitting a WARN()/BUG() from wake_up calls will lead to a deadlock if
> only a single CPU is running.

I think that the deadlock might happen also with more CPUs if
the async_printk() is enabled. I mean:

  printk_emit()
    wake_up_process()
      try_to_wake_up()
	raw_spin_lock_irqsave(&p->pi_lock, flags)  !!!!
	ttwu_queue()
	  ttwu_do_activate()
	    ttwu_activate()
	      activate_task()
		enqueue_task()
		  enqueue_task_fair()	    via p->sched_class->enqueue_task
		    hrtick_update()
		      hrtick_start_fair()
			WARN_ON(task_rq(p) != rq)
			  printk()
			    vprintk_emit()
			      wake_up_process()
				try_to_wake_up()
				  raw_spin_lock_irqsave(&p->pi_lock,
					flags)

There is a deadlock because p->pi_lock is already taken by
the first try_to_wake_up().

By other words, I think that the single running CPU was only
a symptom but it was not the root cause of the deadlock.

> We already had such a situation with system suspend. During a
> specific test on our device sometimes we hit a WARN from the time
> keeping core. (Cannot recall which one exactly. Viresh have it) from
> a printk wake_up path during system suspend and with already only
> one CPU running.
> So we were forced to make printing synchronous in the suspend path
> prior disabling all non-boot cpu's.
> 
> Your solution number 2) sounds reasonable to me.

Good.
 
> I'm wondering if we could hit a WARN()/BUG() somewhere from the fair
> scheduler like the example you made for the RT sched?

Unfortunately, it looks like. The example above actually is from
the fair scheduler.

Best Regards,
Petr

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

#1464894

Hello,

really sorry for very long reply.

On (08/12/16 11:44), Petr Mladek wrote:
[..]
> IMHO, this is fine. We force the synchronous mode in critical
> situations anyway.

yes, I think it makes sense to lower the priority (we also have
briefly discussed this in private emails with Viresh). I'd still
prefer to have forced sync-printk on suspend/hibernate/etc., though.

> But I was curious if we could hit a printk from the wake_up_process().
> The change above causes using the fair scheduler and there is
> the following call chain [*]
> 
>   vprintk_emit()
>   -> wake_up_process()
>    -> try_to_wake_up()
>     -> ttwu_queue()
>      -> ttwu_do_activate()
>       -> ttwu_activate()
>        -> activate_task()
> 	-> enqueue_task()
> 	 -> enqueue_task_fair()	    via p->sched_class->enqueue_task
> 	  -> cfs_rq_of()
> 	   -> task_of()
> 	    -> WARN_ON_ONCE(!entity_is_task(se))
> 
> We should never trigger this because printk_kthread is a task.
> But what if the date gets inconsistent?
> 
> Then there is the following chain:
> 
>   vprintk_emit()
>   -> wake_up_process()
>    -> try_to_wake_up()
>     -> ttwu_queue()
>      -> ttwu_do_activate()
>       -> ttwu_activate()
>        -> activate_task()
> 	-> enqueue_task()
> 	 -> enqueue_task_fair()	    via p->sched_class->enqueue_task
> 	  ->hrtick_update()
> 	   -> hrtick_start_fair()
> 	    -> WARN_ON(task_rq(p) != rq)
> 
> This looks like another paranoid consistency check that might be
> triggered when the scheduler gets messed.
> 
> I see few possible solutions:
> 
> 1. Replace the WARN_ONs by printk_deferred().
> 
>    This is the usual solution but it would make debugging less convenient.

what I did internally was a combination of #1 and #3: I introduced a
dump_stack_deferred() function which is basically (almost) a copy-past
of dump_stack() from lib/dump_stack.c with the difference that it calls
printk_deferred(). and added a WARN_ON_DEFERRED() macro.


> 2. Force synchronous printk inside WARN()/BUG() macros.

will it help? semaphore up() calls wake_up_process() regardless the context.
not to mention that we still may have spin_dump() enabled.


> 3. Force printk_deferred() inside WARN()/BUG() macros via the per-CPU
>    printk_func.
> 
>    It might be elegant. But we do not want this outside the scheduler
>    code. Therefore we would need special variants of  WARN_*_SCHED()
>    BUG_*_SCHED() macros.
>
> I personally prefer the 2nd solution. What do you think about it,
> please?

I personally think a combo of #1 and #3 is a bit better than plain #2.

	-ss

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

#1465042

On Thu 2016-08-18 11:27:12, Sergey Senozhatsky wrote:
> Hello,
> 
> really sorry for very long reply.
> 
> On (08/12/16 11:44), Petr Mladek wrote:
> [..]
> > IMHO, this is fine. We force the synchronous mode in critical
> > situations anyway.
> 
> yes, I think it makes sense to lower the priority (we also have
> briefly discussed this in private emails with Viresh). I'd still
> prefer to have forced sync-printk on suspend/hibernate/etc., though.

Sounds fine to me.

> > But I was curious if we could hit a printk from the wake_up_process().
> > The change above causes using the fair scheduler and there is
> > the following call chain [*]
> > 
> > I see few possible solutions:
> > 
> > 1. Replace the WARN_ONs by printk_deferred().
> > 
> >    This is the usual solution but it would make debugging less convenient.
> 
> what I did internally was a combination of #1 and #3: I introduced a
> dump_stack_deferred() function which is basically (almost) a copy-past
> of dump_stack() from lib/dump_stack.c with the difference that it calls
> printk_deferred(). and added a WARN_ON_DEFERRED() macro.
> 
> 
> > 2. Force synchronous printk inside WARN()/BUG() macros.
> 
> will it help? semaphore up() calls wake_up_process() regardless the context.
> not to mention that we still may have spin_dump() enabled.

Good point. That changes my preferences :-)

> 
> > 3. Force printk_deferred() inside WARN()/BUG() macros via the per-CPU
> >    printk_func.
> > 
> >    It might be elegant. But we do not want this outside the scheduler
> >    code. Therefore we would need special variants of  WARN_*_SCHED()
> >    BUG_*_SCHED() macros.

Also we need to make sure that everything will be done on a single CPU
as the printk_func is per-CPU variable.

> > I personally prefer the 2nd solution. What do you think about it,
> > please?
> 
> I personally think a combo of #1 and #3 is a bit better than plain #2.

I would need to see the code how it looks and if is really works.
But yes, it seems that this is the way to go.

Best Regards,
Petr

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

#1465067

On (08/18/16 11:33), Petr Mladek wrote:
[..]
> > > 2. Force synchronous printk inside WARN()/BUG() macros.
> > 
> > will it help? semaphore up() calls wake_up_process() regardless the context.
> > not to mention that we still may have spin_dump() enabled.
> 
> Good point. That changes my preferences :-)
> 
> > 
> > > 3. Force printk_deferred() inside WARN()/BUG() macros via the per-CPU
> > >    printk_func.
> > > 
> > >    It might be elegant. But we do not want this outside the scheduler
> > >    code. Therefore we would need special variants of  WARN_*_SCHED()
> > >    BUG_*_SCHED() macros.
> 
> Also we need to make sure that everything will be done on a single CPU
> as the printk_func is per-CPU variable.

lib/dump_stack.c dump_stack() disables local IRQs, so we will stay
on the same CPU.

schematically dump_stack_deferred() looks like the one below. I don't
dump registers, that will require one more *_deferred() function.
and as you can see I've replaced show_stack() with save_stack_trace().
it's not entirely universal (as of now), but worked for my needs at
that time.

---

asmlinkage __visible void dump_stack_deferred(void)
{
       unsigned long flags;
       unsigned long stack_trace[16];
       int was_locked;
       int old, cpu;
       int i;

       struct stack_trace trace = {
               .nr_entries = 0,
               .max_entries = ARRAY_SIZE(stack_trace),
               .entries = stack_trace,
               .skip = 0,
       };

       local_irq_save(flags);
retry:
       cpu = smp_processor_id();
       old = atomic_cmpxchg(&dump_lock, -1, cpu);
       if (old == -1) {
               was_locked = 0;
       } else if (old == cpu) {
               was_locked = 1;
       } else {
               cpu_relax();
               goto retry;
       }

       save_stack_trace(&trace);

       for (i = 0; i < trace.nr_entries; i++) {
               printk_deferred("[%p] %pS\n",
                               (void *)stack_trace[i],
                               (void *)stack_trace[i]);
       }

       if (!was_locked)
               atomic_set(&dump_lock, -1);

       local_irq_restore(flags);
}

---

	-ss

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

#1465136

On Thu 2016-08-18 18:51:44, Sergey Senozhatsky wrote:
> On (08/18/16 11:33), Petr Mladek wrote:
> [..]
> > > > 2. Force synchronous printk inside WARN()/BUG() macros.
> > > 
> > > will it help? semaphore up() calls wake_up_process() regardless the context.
> > > not to mention that we still may have spin_dump() enabled.
> > 
> > Good point. That changes my preferences :-)
> > 
> > > 
> > > > 3. Force printk_deferred() inside WARN()/BUG() macros via the per-CPU
> > > >    printk_func.
> > > > 
> > > >    It might be elegant. But we do not want this outside the scheduler
> > > >    code. Therefore we would need special variants of  WARN_*_SCHED()
> > > >    BUG_*_SCHED() macros.
> > 
> > Also we need to make sure that everything will be done on a single CPU
> > as the printk_func is per-CPU variable.
> 
> lib/dump_stack.c dump_stack() disables local IRQs, so we will stay
> on the same CPU.

It is less important to stay of the same CPU if you use
printk_deferred() directly. But it us must to have if you
use it via the printk_func per-CPU variable.

The advantage of the printk_func trick is that it is transparent.
You do not need to modify any existing functions used by WARN()/BUG()
macros.

Best Regards,
Petr

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

#1466053

On (08/18/16 12:56), Petr Mladek wrote:
> On Thu 2016-08-18 18:51:44, Sergey Senozhatsky wrote:
> > On (08/18/16 11:33), Petr Mladek wrote:
> > [..]
> > > > > 2. Force synchronous printk inside WARN()/BUG() macros.
> > > > 
> > > > will it help? semaphore up() calls wake_up_process() regardless the context.
> > > > not to mention that we still may have spin_dump() enabled.
> > > 
> > > Good point. That changes my preferences :-)
> > > 
> > > > 
> > > > > 3. Force printk_deferred() inside WARN()/BUG() macros via the per-CPU
> > > > >    printk_func.
> > > > > 
> > > > >    It might be elegant. But we do not want this outside the scheduler
> > > > >    code. Therefore we would need special variants of  WARN_*_SCHED()
> > > > >    BUG_*_SCHED() macros.
> > > 
> > > Also we need to make sure that everything will be done on a single CPU
> > > as the printk_func is per-CPU variable.
> > 
> > lib/dump_stack.c dump_stack() disables local IRQs, so we will stay
> > on the same CPU.
> 
> It is less important to stay of the same CPU if you use
> printk_deferred() directly. But it us must to have if you
> use it via the printk_func per-CPU variable.
> 
> The advantage of the printk_func trick is that it is transparent.
> You do not need to modify any existing functions used by WARN()/BUG()
> macros.

good point.

so something like below, perhaps. I'm less sure about
deferred BUG()/BUG_ON():

#define DEFERRED_BUG() do { 		\
	printk_deferred_enter();	\
	BUG();				\
	printk_deferred_exit();		\
} while (0)				\

#define DEFERRED_BUG_ON(condition) do { \
	printk_deferred_enter();	\
	BUG_ON(condition);		\
	printk_deferred_exit();		\
} while (0)

depending on .config BUG() may never return back -- passing control
to do_exit(), so printk_deferred_exit() won't be executed. thus we
probably need to have a per-cpu variable that would indicate that
we are in deferred_bug. hm... but do we really need deferred BUG()
in the first place?


Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>

---

 include/asm-generic/bug.h | 50 +++++++++++++++++++++++++++++++++++++++++++++++
 include/linux/printk.h    |  6 ++++++
 kernel/printk/internal.h  | 18 +----------------
 kernel/printk/printk.c    | 42 ++++++++++++++++++++++++++++++++++-----
 4 files changed, 94 insertions(+), 22 deletions(-)

diff --git a/include/asm-generic/bug.h b/include/asm-generic/bug.h
index 6f96247..d72ee1e 100644
--- a/include/asm-generic/bug.h
+++ b/include/asm-generic/bug.h
@@ -60,6 +60,10 @@ struct bug_entry {
  * significant issues that need prompt attention if they should ever
  * appear at runtime.  Use the versions with printk format strings
  * to provide better diagnostics.
+ *
+ * DEFERRED_WARN macros call printk_deferred() to print the messages
+ * and are meant to be used from the contexts where direct printk()
+ * can deadlock the system.
  */
 #ifndef __WARN_TAINT
 extern __printf(3, 4)
@@ -145,6 +149,52 @@ void __warn(const char *file, int line, void *caller, unsigned taint,
 	unlikely(__ret_warn_once);				\
 })
 
+#define DEFERRED_WARN_ON(condition) ({				\
+	int __ret_warn_on = !!(condition);			\
+	if (unlikely(__ret_warn_on)) {				\
+		printk_deferred_enter();			\
+		__WARN();					\
+		printk_deferred_exit();				\
+	}							\
+	unlikely(__ret_warn_on);				\
+})
+
+#define DEFERRED_WARN(condition, format...) ({			\
+	int __ret_warn_on = !!(condition);			\
+	if (unlikely(__ret_warn_on)) {				\
+		printk_deferred_enter();			\
+		__WARN_printf(format);				\
+		printk_deferred_exit();				\
+	}							\
+	unlikely(__ret_warn_on);				\
+})
+
+#define DEFERRED_WARN_ON_ONCE(condition)	({		\
+	static bool __section(.data.unlikely) __warned;		\
+	int __ret_warn_once = !!(condition);			\
+								\
+	if (unlikely(__ret_warn_once && !__warned)) {		\
+		__warned = true;				\
+		printk_deferred_enter();			\
+		WARN_ON(1);					\
+		printk_deferred_exit();				\
+	}							\
+	unlikely(__ret_warn_once);				\
+})
+
+#define DEFERRED_WARN_ONCE(condition, format...)	({	\
+	static bool __section(.data.unlikely) __warned;		\
+	int __ret_warn_once = !!(condition);			\
+								\
+	if (unlikely(__ret_warn_once && !__warned)) {		\
+		__warned = true;				\
+		printk_deferred_enter();			\
+		WARN(1, format);				\
+		printk_deferred_exit();				\
+	}							\
+	unlikely(__ret_warn_once);				\
+})
+
 #else /* !CONFIG_BUG */
 #ifndef HAVE_ARCH_BUG
 #define BUG() do {} while (1)
diff --git a/include/linux/printk.h b/include/linux/printk.h
index 696a56b..5142654 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -193,6 +193,9 @@ void __init setup_log_buf(int early);
 __printf(1, 2) void dump_stack_set_arch_desc(const char *fmt, ...);
 void dump_stack_print_info(const char *log_lvl);
 void show_regs_print_info(const char *log_lvl);
+
+extern void printk_deferred_enter(void);
+extern void printk_deferred_exit(void);
 #else
 static inline __printf(1, 0)
 int vprintk(const char *s, va_list args)
@@ -252,6 +255,9 @@ static inline void dump_stack_print_info(const char *log_lvl)
 static inline void show_regs_print_info(const char *log_lvl)
 {
 }
+
+static void printk_deferred_enter(void) {}
+static void printk_deferred_exit(void) {}
 #endif
 
 extern asmlinkage void dump_stack(void) __cold;
diff --git a/kernel/printk/internal.h b/kernel/printk/internal.h
index 7fd2838..70f1cf2 100644
--- a/kernel/printk/internal.h
+++ b/kernel/printk/internal.h
@@ -19,23 +19,12 @@
 typedef __printf(1, 0) int (*printk_func_t)(const char *fmt, va_list args);
 
 int __printf(1, 0) vprintk_default(const char *fmt, va_list args);
+DECLARE_PER_CPU(printk_func_t, printk_func);
 
 #ifdef CONFIG_PRINTK_NMI
 
 extern raw_spinlock_t logbuf_lock;
 
-/*
- * printk() could not take logbuf_lock in NMI context. Instead,
- * it temporary stores the strings into a per-CPU buffer.
- * The alternative implementation is chosen transparently
- * via per-CPU variable.
- */
-DECLARE_PER_CPU(printk_func_t, printk_func);
-static inline __printf(1, 0) int vprintk_func(const char *fmt, va_list args)
-{
-	return this_cpu_read(printk_func)(fmt, args);
-}
-
 extern atomic_t nmi_message_lost;
 static inline int get_nmi_message_lost(void)
 {
@@ -44,11 +33,6 @@ static inline int get_nmi_message_lost(void)
 
 #else /* CONFIG_PRINTK_NMI */
 
-static inline __printf(1, 0) int vprintk_func(const char *fmt, va_list args)
-{
-	return vprintk_default(fmt, args);
-}
-
 static inline int get_nmi_message_lost(void)
 {
 	return 0;
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 0d3e026..6e260a0 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2026,7 +2026,17 @@ asmlinkage __visible int printk(const char *fmt, ...)
 	int r;
 
 	va_start(args, fmt);
-	r = vprintk_func(fmt, args);
+	/*
+	 * printk() could not take logbuf_lock in NMI context. Instead,
+	 * it temporary stores the strings into a per-CPU buffer. The
+	 * alternative implementation is chosen transparently via per-CPU
+	 * variable.
+	 *
+	 * We also switch printk_func from default to vprintk_deferred()
+	 * when in DEFERRED_WARN()/DEFERRED_BUG(), because it may be
+	 * unsafe to execute vprintk_default().
+	 */
+	r = this_cpu_read(printk_func)(fmt, args);
 	va_end(args);
 
 	return r;
@@ -3037,6 +3047,17 @@ void wake_up_klogd(void)
 	preempt_enable();
 }
 
+static int vprintk_deferred(const char *fmt, va_list args)
+{
+	int r;
+
+	r = vprintk_emit(0, LOGLEVEL_SCHED, NULL, 0, fmt, args);
+	__this_cpu_or(printk_pending, PRINTK_PENDING_OUTPUT);
+	irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
+
+	return r;
+}
+
 int printk_deferred(const char *fmt, ...)
 {
 	va_list args;
@@ -3044,16 +3065,27 @@ int printk_deferred(const char *fmt, ...)
 
 	preempt_disable();
 	va_start(args, fmt);
-	r = vprintk_emit(0, LOGLEVEL_SCHED, NULL, 0, fmt, args);
+	r = vprintk_deferred(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;
 }
 
+void printk_deferred_enter(void)
+{
+	preempt_disable();
+	this_cpu_write(printk_func, vprintk_deferred);
+}
+EXPORT_SYMBOL(printk_deferred_enter);
+
+void printk_deferred_exit(void)
+{
+	this_cpu_write(printk_func, vprintk_default);
+	preempt_enable();
+}
+EXPORT_SYMBOL(printk_deferred_exit);
+
 /*
  * printk rate limiting, lifted from the networking subsystem.
  *
-- 
2.9.3

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

#1466259

On Fri 2016-08-19 15:32:36, Sergey Senozhatsky wrote:
> On (08/18/16 12:56), Petr Mladek wrote:
> > The advantage of the printk_func trick is that it is transparent.
> > You do not need to modify any existing functions used by WARN()/BUG()
> > macros.
> 
> good point.
> 
> so something like below, perhaps. I'm less sure about
> deferred BUG()/BUG_ON():
> 
> #define DEFERRED_BUG() do { 		\
> 	printk_deferred_enter();	\
> 	BUG();				\
> 	printk_deferred_exit();		\
> } while (0)				\
> 
> #define DEFERRED_BUG_ON(condition) do { \
> 	printk_deferred_enter();	\
> 	BUG_ON(condition);		\
> 	printk_deferred_exit();		\
> } while (0)
> 
> depending on .config BUG() may never return back -- passing control
> to do_exit(), so printk_deferred_exit() won't be executed. thus we
> probably need to have a per-cpu variable that would indicate that
> we are in deferred_bug. hm... but do we really need deferred BUG()
> in the first place?

Good question. I am not aware of any BUG_ON() that would be called from
wake_up_process() but it is hard to check everything.

A conservative approach would be to force synchronous printk from
BUG_ON().


> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> 
> ---
> 
>  include/asm-generic/bug.h | 50 +++++++++++++++++++++++++++++++++++++++++++++++
>  include/linux/printk.h    |  6 ++++++
>  kernel/printk/internal.h  | 18 +----------------
>  kernel/printk/printk.c    | 42 ++++++++++++++++++++++++++++++++++-----
>  4 files changed, 94 insertions(+), 22 deletions(-)
> 
> diff --git a/include/asm-generic/bug.h b/include/asm-generic/bug.h
> index 6f96247..d72ee1e 100644
> --- a/include/asm-generic/bug.h
> +++ b/include/asm-generic/bug.h
> @@ -60,6 +60,10 @@ struct bug_entry {
>   * significant issues that need prompt attention if they should ever
>   * appear at runtime.  Use the versions with printk format strings
>   * to provide better diagnostics.
> + *
> + * DEFERRED_WARN macros call printk_deferred() to print the messages
> + * and are meant to be used from the contexts where direct printk()
> + * can deadlock the system.
>   */
>  #ifndef __WARN_TAINT
>  extern __printf(3, 4)
> @@ -145,6 +149,52 @@ void __warn(const char *file, int line, void *caller, unsigned taint,
>  	unlikely(__ret_warn_once);				\
>  })
>  
> +#define DEFERRED_WARN_ON(condition) ({				\
> +	int __ret_warn_on = !!(condition);			\
> +	if (unlikely(__ret_warn_on)) {				\
> +		printk_deferred_enter();			\
> +		__WARN();					\
> +		printk_deferred_exit();				\
> +	}							\
> +	unlikely(__ret_warn_on);				\
> +})

This looks reasonable to me.


> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 0d3e026..6e260a0 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
>  
> +void printk_deferred_enter(void)
> +{
> +	preempt_disable();
> +	this_cpu_write(printk_func, vprintk_deferred);
> +}
> +EXPORT_SYMBOL(printk_deferred_enter);
> +
> +void printk_deferred_exit(void)
> +{
> +	this_cpu_write(printk_func, vprintk_default);
> +	preempt_enable();
> +}
> +EXPORT_SYMBOL(printk_deferred_exit);
> +

This is racy with printk_nmi_enter() and printk_nmi_exit().
It need to work both ways. It must keep printk_deferred()
even when DEFERRED_WARN_ON() is called in nmi context.
Also it must keep printk_deferred() when the DEFERRED_WARN_ON()
is interrupted by an nmi.

It think that best solution would be to allow nesting.
What about replacing "printk_func" per-CPU variable
with a per-CPU atomic counter. Then we could just
check the counter in vprintk_emit() to see if it is
deferred or not.

The approach with printk_func() was more generic. We thought
that it might be used even for a transparent early_printk().
But it still might be solved even with the per-CPU atomic
counter. We could fallback to the early_printk when a
global flag is set or so.

Best Regards,
Petr

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

#1466618

On Fri 19-08-16 11:54:55, Petr Mladek wrote:
> On Fri 2016-08-19 15:32:36, Sergey Senozhatsky wrote:
> > On (08/18/16 12:56), Petr Mladek wrote:
> > > The advantage of the printk_func trick is that it is transparent.
> > > You do not need to modify any existing functions used by WARN()/BUG()
> > > macros.
> > 
> > good point.
> > 
> > so something like below, perhaps. I'm less sure about
> > deferred BUG()/BUG_ON():
> > 
> > #define DEFERRED_BUG() do { 		\
> > 	printk_deferred_enter();	\
> > 	BUG();				\
> > 	printk_deferred_exit();		\
> > } while (0)				\
> > 
> > #define DEFERRED_BUG_ON(condition) do { \
> > 	printk_deferred_enter();	\
> > 	BUG_ON(condition);		\
> > 	printk_deferred_exit();		\
> > } while (0)
> > 
> > depending on .config BUG() may never return back -- passing control
> > to do_exit(), so printk_deferred_exit() won't be executed. thus we
> > probably need to have a per-cpu variable that would indicate that
> > we are in deferred_bug. hm... but do we really need deferred BUG()
> > in the first place?
> 
> Good question. I am not aware of any BUG_ON() that would be called from
> wake_up_process() but it is hard to check everything.
> 
> A conservative approach would be to force synchronous printk from
> BUG_ON().

Just a quick thought: Cannot we just do printk_deferred_enter() when we are
about to call into the scheduler from printk code and printk_deferred_exit()
when leaving it? That would look like the least error-prone way how
handling this kind of recursion...

OTOH there's also the other possible direction for the recursion when we
are in the scheduler, holding some scheduler locks, decide to WARN which
enters printk, that ends up calling wake_up_process() which deadlocks
on scheduler locks... I don't see how to handle this type of recursion
inside the printk code itself easily and so far the answer was - use
printk_deferred() in the scheduler and don't use WARN...

Hum, maybe we could add lockdep annotation to a WARN_ON and BUG_ON macros so
that it would grab and release console_sem (even if the condition is false).
That way we'd get lockdep splats for all the possible WARN_ON and BUG_ON
calls that could deadlock.

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

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

#1466775

On (08/19/16 21:00), Jan Kara wrote:
> > > depending on .config BUG() may never return back -- passing control
> > > to do_exit(), so printk_deferred_exit() won't be executed. thus we
> > > probably need to have a per-cpu variable that would indicate that
> > > we are in deferred_bug. hm... but do we really need deferred BUG()
> > > in the first place?
> > 
> > Good question. I am not aware of any BUG_ON() that would be called from
> > wake_up_process() but it is hard to check everything.
> > 
> > A conservative approach would be to force synchronous printk from
> > BUG_ON().
> 
> Just a quick thought: Cannot we just do printk_deferred_enter() when we are
> about to call into the scheduler from printk code and printk_deferred_exit()
> when leaving it? That would look like the least error-prone way how
> handling this kind of recursion...

interesting idea.
printk_deferred_enter() increments preempt count, so there may be additional
obstacles and, as a result, ad-hocs, that scheduler people will sincerely hate.
need to think more.

> OTOH there's also the other possible direction for the recursion when we
> are in the scheduler, holding some scheduler locks, decide to WARN which
> enters printk, that ends up calling wake_up_process() which deadlocks
> on scheduler locks... I don't see how to handle this type of recursion
> inside the printk code itself easily and so far the answer was - use
> printk_deferred() in the scheduler and don't use WARN...

the recursion detection is really tricky, yes. it seems (and I haven't
thought of it good enough) to be a bit simpler when we operate in async
printk mode, because we remove this uncontrollable console_unlock().
so we can do something like this:

vprintk_emit(....)
{
	local_irq_save();

	if (this_cpu_read(in_printk)) {
		log_store(BUG: printk recursion!");
		goto out;
	}

	this_cpu_write(in_printk) = 1;

	raw_spin_lock(&logbuf_lock);
	log_store();
	raw_spin_unlock(&logbuf_lock);

	if (!in_sched) {
		if (console_loglevel != CONSOLE_LOGLEVEL_MOTORMOUTH &&
				can_printk_async()) {
			printk_kthread_need_flush_console = true;
			wake_up_process(printk_kthread);
		}
	}

	this_cpu_write(in_printk) = 0;
out:
	local_irq_restore();
}

async printk mode from this point of view is sort of atomic.
we can even set different values of per-CPU `in_printk' on various
stages of printk, which will permit to have better recursion handling.
for example, if we recurse from raw_spin_unlock(&logbuf_lock) then we
must re-init logbuf_lock, because it's 99% corrupted... and so on. but
I haven't really thought of it yet. it obviously doesn't work for sync
printk mode.

> Hum, maybe we could add lockdep annotation to a WARN_ON and BUG_ON macros so
> that it would grab and release console_sem (even if the condition is false).
> That way we'd get lockdep splats for all the possible WARN_ON and BUG_ON
> calls that could deadlock.

hm.

	-ss

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

#1467341

Hello,

On (08/20/16 14:24), Sergey Senozhatsky wrote:
> On (08/19/16 21:00), Jan Kara wrote:
> > > > depending on .config BUG() may never return back -- passing control
> > > > to do_exit(), so printk_deferred_exit() won't be executed. thus we
> > > > probably need to have a per-cpu variable that would indicate that
> > > > we are in deferred_bug. hm... but do we really need deferred BUG()
> > > > in the first place?
> > > 
> > > Good question. I am not aware of any BUG_ON() that would be called from
> > > wake_up_process() but it is hard to check everything.
> > > 
> > > A conservative approach would be to force synchronous printk from
> > > BUG_ON().
> > 
> > Just a quick thought: Cannot we just do printk_deferred_enter() when we are
> > about to call into the scheduler from printk code and printk_deferred_exit()
> > when leaving it? That would look like the least error-prone way how
> > handling this kind of recursion...
> 
> interesting idea.
> printk_deferred_enter() increments preempt count, so there may be additional
> obstacles and, as a result, ad-hocs, that scheduler people will sincerely hate.
> need to think more.

so we probably can try something like this

---

diff --git a/kernel/sched/core.c b/kernel/sched/core.c
index 2add7c5..b23f919 100644
--- a/kernel/sched/core.c
+++ b/kernel/sched/core.c
@@ -2014,6 +2014,7 @@ try_to_wake_up(struct task_struct *p, unsigned int state, int wake_flags)
         * set_current_state() the waiting thread does.
         */
        smp_mb__before_spinlock();
+       printk_deferred_enter();
        raw_spin_lock_irqsave(&p->pi_lock, flags);
        if (!(p->state & state))
                goto out;
@@ -2073,6 +2074,7 @@ stat:
                ttwu_stat(p, cpu, wake_flags);
 out:
        raw_spin_unlock_irqrestore(&p->pi_lock, flags);
+       printk_deferred_exit();
 
        return success;
 }


---

since we are basically interested in wake_up_process() only from
printk() POV. not sure how acceptable 2 * preempt_count and 2 * per-CPU
writes for every try_to_wake_up().


the other thing I just thought of is doing something as follows
!!!not tested, will not compile, just an idea!!!

---

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 6e260a0..bb8d719 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1789,6 +1789,7 @@ asmlinkage int vprintk_emit(int facility, int level,
        printk_delay();
 
        local_irq_save(flags);
+       printk_nmi_enter();
        this_cpu = smp_processor_id();
 
        /*
@@ -1804,6 +1805,7 @@ asmlinkage int vprintk_emit(int facility, int level,
                 */
                if (!oops_in_progress && !lockdep_recursing(current)) {
                        recursion_bug = true;
+                       printk_nmi_exit();
                        local_irq_restore(flags);
                        return 0;
                }
@@ -1920,6 +1922,7 @@ asmlinkage int vprintk_emit(int facility, int level,
        logbuf_cpu = UINT_MAX;
        raw_spin_unlock(&logbuf_lock);
        lockdep_on();
+       printk_nmi_exit();
        local_irq_restore(flags);
 
        /* If called from the scheduler, we can not call up(). */
---

so may be we will not blow up in case of spin_dump() on logbuf_lock.
well, if logbuf_lock was corrupted then nothing will help us -- it's over.
but if raw_spin_lock(&logbuf_lock), for instance, spin_dump()-s because
logbuf_lock was not released after `loops_per_jiffy * HZ' then deferred
printing may help.


probably we can make NMI printk_func to be more general way of using
an alternative-printk buffer and, for example, rename API it to
printk_alternative_enter() and printk_alternative_exit(), not to confuse
anyone. (yes, NMIs are not available on every platform)


and even more. we can start dump_stack() from recursion detection path
to that alternative printk-buffer, which is a bit more helpful than
"BUG: recent printk recursion!"
!!!not tested, will not compile, just an idea!!!

---

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 6e260a0..ebce39a 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1789,6 +1789,7 @@ asmlinkage int vprintk_emit(int facility, int level,
        printk_delay();
 
        local_irq_save(flags);
+       printk_nmi_enter();
        this_cpu = smp_processor_id();
 
        /*
@@ -1804,6 +1805,8 @@ asmlinkage int vprintk_emit(int facility, int level,
                 */
                if (!oops_in_progress && !lockdep_recursing(current)) {
                        recursion_bug = true;
+                       WARN_ON(1);		/* <<< dump_stack to alternative buffer */
+                       printk_nmi_exit();
                        local_irq_restore(flags);
                        return 0;
                }
@@ -1816,14 +1819,8 @@ asmlinkage int vprintk_emit(int facility, int level,
        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));
+               printk_nmi_flush();
        }
 
        nmi_message_lost = get_nmi_message_lost();
@@ -1920,6 +1917,7 @@ asmlinkage int vprintk_emit(int facility, int level,
        logbuf_cpu = UINT_MAX;
        raw_spin_unlock(&logbuf_lock);
        lockdep_on();
+       printk_nmi_exit();
        local_irq_restore(flags);
 
        /* If called from the scheduler, we can not call up(). */

---

just some quick thoughts.


	-ss

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

#1468529

On Mon 2016-08-22 13:15:20, Sergey Senozhatsky wrote:
> Hello,
> 
> On (08/20/16 14:24), Sergey Senozhatsky wrote:
> > On (08/19/16 21:00), Jan Kara wrote:
> > > > > depending on .config BUG() may never return back -- passing control
> > > > > to do_exit(), so printk_deferred_exit() won't be executed. thus we
> > > > > probably need to have a per-cpu variable that would indicate that
> > > > > we are in deferred_bug. hm... but do we really need deferred BUG()
> > > > > in the first place?
> > > > 
> > > > Good question. I am not aware of any BUG_ON() that would be called from
> > > > wake_up_process() but it is hard to check everything.
> > > > 
> > > > A conservative approach would be to force synchronous printk from
> > > > BUG_ON().
> > > 
> > > Just a quick thought: Cannot we just do printk_deferred_enter() when we are
> > > about to call into the scheduler from printk code and printk_deferred_exit()
> > > when leaving it? That would look like the least error-prone way how
> > > handling this kind of recursion...
> > 
> > interesting idea.
> > printk_deferred_enter() increments preempt count, so there may be additional
> > obstacles and, as a result, ad-hocs, that scheduler people will sincerely hate.
> > need to think more.
> 
> the other thing I just thought of is doing something as follows
> !!!not tested, will not compile, just an idea!!!
> 
> ---
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 6e260a0..bb8d719 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -1789,6 +1789,7 @@ asmlinkage int vprintk_emit(int facility, int level,
>         printk_delay();
>  
>         local_irq_save(flags);
> +       printk_nmi_enter();
>         this_cpu = smp_processor_id();

Huh, this looks very interesting but I am afraid that it will not fly.
The problem is that vprintk_nmi() is safe only when it is used
exclusively in NMI.

The following could happen with your code:

/**** normar context ****/
vprintk_emit()
  printk_nmi_enter()
  ...
  wake_up_process()
    WARN()
      printk()
	vprintk_nmi()
	  vsnprintf(..., "0123456789")

	    /* real NMI comes after writing "01234" */
	    /**** NMI context ****/
	    vprintk_nmi();
	      vsnprintf(..., "abcdefghijklmno");

	    /**** normal context ****/
	    /* we finish writing "56789" into the buffer */

=> part of the message from NMI gets broken "abcde56789klmno".

The lockless handling of the NMI per-CPU buffer already is not
trivial. I would be afraid to add more hacks to make
it writable in all contexts.

I am sorry about the bad news. This was so promising on the first
look.

Best Regards,
Petr

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

#1469012

On (08/23/16 14:19), Petr Mladek wrote:
> > the other thing I just thought of is doing something as follows
> > !!!not tested, will not compile, just an idea!!!
> > 
> > ---
> > 
> > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> > index 6e260a0..bb8d719 100644
> > --- a/kernel/printk/printk.c
> > +++ b/kernel/printk/printk.c
> > @@ -1789,6 +1789,7 @@ asmlinkage int vprintk_emit(int facility, int level,
> >         printk_delay();
> >  
> >         local_irq_save(flags);
> > +       printk_nmi_enter();
> >         this_cpu = smp_processor_id();
> 
> Huh, this looks very interesting but I am afraid that it will not fly.
> The problem is that vprintk_nmi() is safe only when it is used
> exclusively in NMI.
> 
> The following could happen with your code:

sure. I took NMI as a quick and easy example that did not require a lot
of words to explain because you guys are familiar with NMI printing.
the thing is - we don't have to share the same buffer with the actual NMI,
but instead have our own small 'alternative-printk' per-cpu buffers (a page
or two, perhaps). it's up to `printk_func' that we set up at the entry point
and flush function that we execute later. vprintk_nmi() writes to
this_cpu_ptr(&nmi_print_seq), vprintk_alter() will write to
this_cpu_ptr(&alt_print_seq), for example. the same with flushing:
printk_nmi_flush reads in from per_cpu(nmi_print_seq); alter-printk flush
can read from per_cpu(alt_print_seq).

[..]
> The lockless handling of the NMI per-CPU buffer already is not
> trivial. I would be afraid to add more hacks to make
> it writable in all contexts.

yes. we can reuse the idea of NMI printk and most of the code. the thing
we really care is `struct nmi_seq_buf' assigned to this particular CPU,
and there can be several seq_buffer-s.

> I am sorry about the bad news. This was so promising on the first
> look.

it's not dead yet ;)

	-ss

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

#1468547

On Sat 2016-08-20 14:24:30, Sergey Senozhatsky wrote:
> On (08/19/16 21:00), Jan Kara wrote:
> > > > depending on .config BUG() may never return back -- passing control
> > > > to do_exit(), so printk_deferred_exit() won't be executed. thus we
> > > > probably need to have a per-cpu variable that would indicate that
> > > > we are in deferred_bug. hm... but do we really need deferred BUG()
> > > > in the first place?
> > > 
> > > Good question. I am not aware of any BUG_ON() that would be called from
> > > wake_up_process() but it is hard to check everything.
> > > 
> > > A conservative approach would be to force synchronous printk from
> > > BUG_ON().
> > 
> > Just a quick thought: Cannot we just do printk_deferred_enter() when we are
> > about to call into the scheduler from printk code and printk_deferred_exit()
> > when leaving it? That would look like the least error-prone way how
> > handling this kind of recursion...
> 
> interesting idea.
> printk_deferred_enter() increments preempt count, so there may be additional
> obstacles and, as a result, ad-hocs, that scheduler people will sincerely hate.
> need to think more.

I wonder if this would be acceptable at least for
wake_up_process(). It seems to be the only scheduler function that we
are interested in. And we might call it from vprintk

> > OTOH there's also the other possible direction for the recursion when we
> > are in the scheduler, holding some scheduler locks, decide to WARN which
> > enters printk, that ends up calling wake_up_process() which deadlocks
> > on scheduler locks... I don't see how to handle this type of recursion
> > inside the printk code itself easily and so far the answer was - use
> > printk_deferred() in the scheduler and don't use WARN...
> 
> the recursion detection is really tricky, yes. it seems (and I haven't
> thought of it good enough) to be a bit simpler when we operate in async
> printk mode, because we remove this uncontrollable console_unlock().
> so we can do something like this:
> 
> vprintk_emit(....)
> {
> 	local_irq_save();
> 
> 	if (this_cpu_read(in_printk)) {
> 		log_store(BUG: printk recursion!");
> 		goto out;
> 	}

This does not quarantee that we have the logbug_lock. We might endup
here from the raw_spin_lock() call and the lock might be owned by
another CPU.

I am afraid that we could only set some global variable here.

> 
> 	this_cpu_write(in_printk) = 1;
> 
> 	raw_spin_lock(&logbuf_lock);
> 	log_store();
> 	raw_spin_unlock(&logbuf_lock);
> 
> 	if (!in_sched) {
> 		if (console_loglevel != CONSOLE_LOGLEVEL_MOTORMOUTH &&
> 				can_printk_async()) {
> 			printk_kthread_need_flush_console = true;
> 			wake_up_process(printk_kthread);
> 		}
> 	}
> 
> 	this_cpu_write(in_printk) = 0;
> out:
> 	local_irq_restore();
> }
>
> async printk mode from this point of view is sort of atomic.

This would prevent using printk_deferred() from the scheduler code.

A solution would be to set the per-CPU variable only around the
wake_up_process() call. Well, it is orthogonal to using
printk_deferred_enter() around calling wake_up_process().

Best Regards,
Petr

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

#1468561

On Fri 2016-08-19 21:00:07, Jan Kara wrote:
> On Fri 19-08-16 11:54:55, Petr Mladek wrote:
> > On Fri 2016-08-19 15:32:36, Sergey Senozhatsky wrote:
> > > On (08/18/16 12:56), Petr Mladek wrote:
> > > > The advantage of the printk_func trick is that it is transparent.
> > > > You do not need to modify any existing functions used by WARN()/BUG()
> > > > macros.
> > > 
> > > good point.
> > > 
> > > so something like below, perhaps. I'm less sure about
> > > deferred BUG()/BUG_ON():
> > > 
> > > #define DEFERRED_BUG() do { 		\
> > > 	printk_deferred_enter();	\
> > > 	BUG();				\
> > > 	printk_deferred_exit();		\
> > > } while (0)				\
> > > 
> > > #define DEFERRED_BUG_ON(condition) do { \
> > > 	printk_deferred_enter();	\
> > > 	BUG_ON(condition);		\
> > > 	printk_deferred_exit();		\
> > > } while (0)
> > > 
> > > depending on .config BUG() may never return back -- passing control
> > > to do_exit(), so printk_deferred_exit() won't be executed. thus we
> > > probably need to have a per-cpu variable that would indicate that
> > > we are in deferred_bug. hm... but do we really need deferred BUG()
> > > in the first place?
> > 
> > Good question. I am not aware of any BUG_ON() that would be called from
> > wake_up_process() but it is hard to check everything.
> > 
> > A conservative approach would be to force synchronous printk from
> > BUG_ON().
> 
> Just a quick thought: Cannot we just do printk_deferred_enter() when we are
> about to call into the scheduler from printk code and printk_deferred_exit()
> when leaving it? That would look like the least error-prone way how
> handling this kind of recursion...
> 
> OTOH there's also the other possible direction for the recursion when we
> are in the scheduler, holding some scheduler locks, decide to WARN which
> enters printk, that ends up calling wake_up_process() which deadlocks
> on scheduler locks... I don't see how to handle this type of recursion
> inside the printk code itself easily and so far the answer was - use
> printk_deferred() in the scheduler and don't use WARN...
> 
> Hum, maybe we could add lockdep annotation to a WARN_ON and BUG_ON macros so
> that it would grab and release console_sem (even if the condition is false).
> That way we'd get lockdep splats for all the possible WARN_ON and BUG_ON
> calls that could deadlock.

The idea is interesting but I think that we do not want the fake
grab/release of the console_sem.

We use console_trylock() in vprintk_emit(). Please note the "try"
variant. So it is safe to call a nested printk() from the console code.

IMHO, we want to avoid calling console from the scheduler code because:

  1. console is slow and we do not want to block the scheduler.

  2. console_unlock() calls wake_up_process() and we do not want
     a deadlock by the scheduler locks.


Therefore I think that we want to detect something specific
from the scheduler that is also reachable from WARN()/printk().

Best Regards,
Petr

PS: My brain rotated several times this day around these problems.
I hope that my opinion still makes some sense :-)

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web