[PATCH RT] printk: console must not schedule for drivers

[PATCH RT] printk: console must not schedule for drivers

[John Ogness]

Even though the printk kthread is always preemptible, it is still not
allowed to call cond_resched() from within console drivers. The
task may become non-preemptible in the console driver call chain. For
example, vt_console_print() takes a spinlock and then can call into
fbcon_redraw(), which can conditionally invoke cond_resched():

BUG: sleeping function called from invalid context at kernel/printk/printk.c:2322
in_atomic(): 1, irqs_disabled(): 0, non_block: 0, pid: 177, name: printk
CPU: 0 PID: 177 Comm: printk Not tainted 5.6.2-00011-ga536059557f1d9 #1
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.12.0-1 04/01/2014
Call Trace:
 dump_stack+0x66/0x8b
 ___might_sleep+0x102/0x120
 console_conditional_schedule+0x24/0x30
 fbcon_redraw+0x96/0x1c0
 ? fbcon_cursor+0x100/0x190
 fbcon_scroll+0x556/0xd70
 con_scroll+0x147/0x1e0
 lf+0x9e/0xb0
 vt_console_print+0x253/0x3d0
 printk_kthread_func+0x1d5/0x3b0

Disable cond_resched() for the call into the console drivers.

Reported-by: kernel test robot <rong.a.chen@intel.com>
Signed-off-by: John Ogness <john.ogness@linutronix.de>
---
 kernel/printk/printk.c | 1 +
 1 file changed, 1 insertion(+)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 8821a8c2263f..8bc683be0857 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2715,6 +2715,7 @@ static int printk_kthread_func(void *data)
 			    &len, printk_time);
 
 		console_lock();
+		console_may_schedule = 0;
 		call_console_drivers(master_seq, ext_text, ext_len, text, len,
 				     msg->level, msg->facility);
 		if (len > 0 || ext_len > 0)
-- 
2.19.0

Re: [PATCH RT] printk: console must not schedule for drivers

[Sebastian Andrzej Siewior]

On 2020-04-06 23:22:17 [+0200], John Ogness wrote:
> Even though the printk kthread is always preemptible, it is still not
> allowed to call cond_resched() from within console drivers. The
> task may become non-preemptible in the console driver call chain. For
> example, vt_console_print() takes a spinlock and then can call into
> fbcon_redraw(), which can conditionally invoke cond_resched():
> 
> BUG: sleeping function called from invalid context at kernel/printk/printk.c:2322
> in_atomic(): 1, irqs_disabled(): 0, non_block: 0, pid: 177, name: printk
> CPU: 0 PID: 177 Comm: printk Not tainted 5.6.2-00011-ga536059557f1d9 #1
> Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.12.0-1 04/01/2014
> Call Trace:
>  dump_stack+0x66/0x8b
>  ___might_sleep+0x102/0x120
>  console_conditional_schedule+0x24/0x30
>  fbcon_redraw+0x96/0x1c0
>  ? fbcon_cursor+0x100/0x190
>  fbcon_scroll+0x556/0xd70
>  con_scroll+0x147/0x1e0
>  lf+0x9e/0xb0
>  vt_console_print+0x253/0x3d0
>  printk_kthread_func+0x1d5/0x3b0
> 
> Disable cond_resched() for the call into the console drivers.

Interesting. So you get a report and I don't?

I have also patch related questions :)
- So before the re-rewrite, console_unlock() set this 0 before invoking
  the console drivers so it was always 0. I assume it was called with
  disabled interrupts.

- Is there a scenario in fbcon where this function is invoked and
  console_may_schedule is not 0?

Sebastian

Re: [PATCH RT] printk: console must not schedule for drivers

[John Ogness]

On 2020-04-15, Sebastian Andrzej Siewior <bigeasy@linutronix.de> wrote:
>> Even though the printk kthread is always preemptible, it is still not
>> allowed to call cond_resched() from within console drivers. The
>> task may become non-preemptible in the console driver call chain. For
>> example, vt_console_print() takes a spinlock and then can call into
>> fbcon_redraw(), which can conditionally invoke cond_resched():
>> 
>> BUG: sleeping function called from invalid context at
>> kernel/printk/printk.c:2322
>> in_atomic(): 1, irqs_disabled(): 0, non_block: 0, pid: 177, name: printk
>> CPU: 0 PID: 177 Comm: printk Not tainted 5.6.2-00011-ga536059557f1d9 #1
>> Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.12.0-1
>> 04/01/2014
>> Call Trace:
>>  dump_stack+0x66/0x8b
>>  ___might_sleep+0x102/0x120
>>  console_conditional_schedule+0x24/0x30
>>  fbcon_redraw+0x96/0x1c0
>>  ? fbcon_cursor+0x100/0x190
>>  fbcon_scroll+0x556/0xd70
>>  con_scroll+0x147/0x1e0
>>  lf+0x9e/0xb0
>>  vt_console_print+0x253/0x3d0
>>  printk_kthread_func+0x1d5/0x3b0
>> 
>> Disable cond_resched() for the call into the console drivers.
>
> Interesting. So you get a report and I don't?

Apparently only the patch author was notified. The reporter should
include all the people tagged in the patch. I'll send him an email about
this.

> - So before the re-rewrite, console_unlock() set this 0 before
>   invoking the console drivers so it was always 0. I assume it was
>   called with disabled interrupts.

Correct.

> - Is there a scenario in fbcon where this function is invoked and
>   console_may_schedule is not 0?

Yes. The ttys/consoles are invoked through other call chains not related
to printk. Since console_lock() can sleep, any caller of console_lock()
_should_ be allowed to perform the cond_resched(). (The printk thread is
an exception here!)

Here is one call chain I picked out:

tty_io.c:tty_write_message()
    mutex_lock()
    tty->ops->write() -> usb-serial.c:serial_write()
        port->serial->type->write() -> vt.c:con_write()
            do_con_write()
                console_lock()
                    console_may_schedule = 1;
                console_conditional_schedule();
                    cond_resched();

From the mutex_lock() we can see that we are in a non-atomic context. In
this case it is OK to call console_lock() and cond_resched().

John Ogness

Re: [PATCH RT] printk: console must not schedule for drivers

[Sebastian Andrzej Siewior]

On 2020-04-16 10:13:23 [+0200], John Ogness wrote:
> > - So before the re-rewrite, console_unlock() set this 0 before
> >   invoking the console drivers so it was always 0. I assume it was
> >   called with disabled interrupts.
> 
> Correct.

le me apply that even if it looks like a fix at the wrong spot. However,
it only affects PREEMPT_VOLUNTARY so…

> John Ogness

Sebastian

Re: [PATCH RT] printk: console must not schedule for drivers

[John Ogness]

On 2020-04-16, John Ogness <john.ogness@linutronix.de> wrote:
>> - Is there a scenario in fbcon where this function is invoked and
>>   console_may_schedule is not 0?

Sorry, I overlooked that you were specifically asking about fbcon. In
console_conditional_schedule() when it is going to call cond_resched(),
I added a WARN_ON() with a condition that it would only trigger in
fbcon. This allowed me to quickly generate a backtrace. This is what
showed up (upon hitting the return key in the graphical console):

[   19.694698][ T1301] Call Trace:
[   19.694743][ T1301]  dump_stack+0xa0/0xea
[   19.694766][ T1301]  console_conditional_schedule+0xac/0xc0
[   19.694779][ T1301]  fbcon_redraw.isra.16+0x1d2/0x460
[   19.694825][ T1301]  fbcon_scroll+0x1b28/0x36d0
[   19.694872][ T1301]  con_scroll+0x2dd/0x650
[   19.694914][ T1301]  lf+0x240/0x2a0
[   19.694930][ T1301]  ? con_scroll+0x650/0x650
[   19.694948][ T1301]  ? find_held_lock+0x36/0x1d0
[   19.694983][ T1301]  do_con_trol+0x33c/0x6720
[   19.695001][ T1301]  ? lock_downgrade+0x850/0x850
[   19.695019][ T1301]  ? reset_palette+0x210/0x210
[   19.695051][ T1301]  ? __kasan_check_read+0x11/0x20
[   19.695080][ T1301]  ? __atomic_notifier_call_chain+0x9a/0x110
[   19.695108][ T1301]  do_con_write.part.28+0xae2/0x1ba0
[   19.695179][ T1301]  ? do_con_trol+0x6720/0x6720
[   19.695195][ T1301]  ? mutex_lock_io_nested+0x1240/0x1240
[   19.695212][ T1301]  ? console_unlock+0x67d/0xac0
[   19.695238][ T1301]  ? __kasan_check_write+0x14/0x20
[   19.695249][ T1301]  ? __mutex_unlock_slowpath+0xe5/0x6a0
[   19.695287][ T1301]  con_write+0x24/0x90
[   19.695305][ T1301]  do_output_char+0x4f8/0x710
[   19.695330][ T1301]  n_tty_write+0x52b/0xfc0
[   19.695345][ T1301]  ? __might_fault+0xcb/0x1b0
[   19.695400][ T1301]  ? n_tty_read+0x1900/0x1900
[   19.695419][ T1301]  ? prepare_to_wait_exclusive+0x2f0/0x2f0
[   19.695444][ T1301]  ? __kasan_check_write+0x14/0x20
[   19.695469][ T1301]  tty_write+0x3ba/0x800
[   19.695492][ T1301]  ? n_tty_read+0x1900/0x1900
[   19.695519][ T1301]  __vfs_write+0x66/0x120
[   19.695541][ T1301]  vfs_write+0x19c/0x4b0
[   19.695568][ T1301]  ksys_write+0x110/0x230
[   19.695588][ T1301]  ? __ia32_sys_read+0xb0/0xb0
[   19.695604][ T1301]  ? do_syscall_64+0x1d/0x470
[   19.695617][ T1301]  ? entry_SYSCALL_64_after_hwframe+0x49/0xb3
[   19.695646][ T1301]  __x64_sys_write+0x73/0xb0
[   19.695664][ T1301]  do_syscall_64+0x9a/0x470
[   19.695684][ T1301]  entry_SYSCALL_64_after_hwframe+0x49/0xb3

So the answer to your question is "yes".

It would probably be a good idea if vt_console_print() could set
console_may_schedule=0 after taking the printing_lock (spinlock).

There are probably more of these quirky cases hiding in the kernel. I've
taken note of this and will look into it when I get some free cycles.

John Ogness