Re: v5.19-rc2-rt3: nouveau might sleep splat

[Sebastian Andrzej Siewior <bigeasy@linutronix.de>]

+ John

On 2022-06-24 11:52:26 [+0200], Mike Galbraith wrote:
> On Fri, 2022-06-24 at 10:42 +0200, Sebastian Andrzej Siewior wrote:
> > On 2022-06-18 11:25:39 [+0200], Mike Galbraith wrote:
> > > I haven't done any digging to see why this now happens where it
> > > previously did not.
> >
> > I don't see where interrupts have been disabled but they have been. The
> > printk path should yell earlier but did not the crng path is kind of
> > late and I don't see anything obvious in between.
> 
> Allegedly vprintk_store().
> 
> (gdb) list *vprintk_store+0x3cc
> 0xffffffff8114283c is in vprintk_store (kernel/printk/printk.c:2280).
> warning: Source file is more recent than executable.
> 2275            u32 caller_id;
> 2276            u16 text_len;
> 2277            int ret = 0;
> 2278            u64 ts_nsec;
> 2279
> 2280            if (!printk_enter_irqsave(recursion_ptr, irqflags))
> 2281                    return 0;
> 2282
> 2283            /*
> 2284             * Since the duration of printk() can vary depending on the message
> (gdb)

ehm. Why do we need to keep interrupts disabled for vsnprintf()?
Wouldn't it work to move that lock a few lines below where it is
actually needed?

> [    6.520357] BUG: sleeping function called from invalid context at kernel/locking/spinlock_rt.c:46
> [    6.520358] in_atomic(): 0, irqs_disabled(): 1, non_block: 0, pid: 399, name: systemd-udevd
> [    6.520359] preempt_count: 0, expected: 0
> [    6.520359] RCU nest depth: 1, expected: 1
> [    6.520360] 5 locks held by systemd-udevd/399:
> [    6.520361]  #0: ffff909a815821a8 (&dev->mutex){....}-{3:3}, at: __driver_attach+0xa1/0x170
> [    6.520367]  #1: ffff909a912b0a98 (&helper->lock){+.+.}-{3:3}, at: drm_fb_helper_initial_config+0x26/0x40 [drm_kms_helper]
> [    6.520383]  #2: ffffffffbd8e91b8 (filling){....}-{2:2}, at: default_pointer+0x17e/0x2d0
> [    6.520387]  #3: ffffffffbd7929a0 (rcu_read_lock){....}-{1:2}, at: rt_spin_trylock+0x36/0xd0
> [    6.520391]  #4: ffff909d8ea335a0 ((crngs.lock)){+.+.}-{2:2}, at: crng_make_state+0x76/0x1c0
> [    6.520394] irq event stamp: 843364
> [    6.520394] hardirqs last  enabled at (843363): [<ffffffffbc7dfb10>] _raw_spin_unlock_irqrestore+0x30/0x77
> [    6.520397] hardirqs last disabled at (843364): [<ffffffffbbd4283c>] vprintk_store+0x3cc/0x550
> [    6.520399] softirqs last  enabled at (151950): [<ffffffffbbcb8223>] __local_bh_enable_ip+0xc3/0x150
> [    6.520401] softirqs last disabled at (151944): [<ffffffffbbe8c135>] btf_alloc_id+0x5/0xb0
> [    6.520404] CPU: 0 PID: 399 Comm: systemd-udevd Tainted: G        W   E     5.19.0.gca1fdab-master-rt #5 2262f40963ee88d2873a82a86160b299ace0d165
> [    6.520406] Hardware name: MEDION MS-7848/MS-7848, BIOS M7848W08.20C 09/23/2013
> [    6.520407] Call Trace:
> [    6.520408]  <TASK>
> [    6.520409]  dump_stack_lvl+0x55/0x6d
> [    6.520413]  __might_resched+0x1aa/0x1e0
> [    6.520418]  rt_spin_lock+0x4d/0xe0
> [    6.520419]  ? crng_make_state+0x76/0x1c0
> [    6.520422]  crng_make_state+0x76/0x1c0
> [    6.520426]  _get_random_bytes.part.16+0x4e/0x110
> [    6.520428]  ? rt_spin_trylock+0x36/0xd0
> [    6.520432]  ? preempt_count_sub+0x43/0x50
> [    6.520434]  ? rt_spin_trylock+0x8b/0xd0
> [    6.520435]  ? rt_spin_trylock+0x8b/0xd0
> [    6.520438]  ? migrate_disable+0x119/0x120
> [    6.520442]  default_pointer+0x2a0/0x2d0
> [    6.520448]  vsnprintf+0x35a/0x4c0
> [    6.520449]  ? kernel_text_address+0xaa/0xc0
> [    6.520454]  va_format.isra.16+0x6e/0xa0
> [    6.520459]  vsnprintf+0x35a/0x4c0
> [    6.520464]  vprintk_store+0x150/0x550
> [    6.520468]  ? string+0x40/0x50
> [    6.520472]  ? vsnprintf+0x48f/0x4c0
> [    6.520480]  vprintk_emit+0x44/0x170
> [    6.520482]  ? __lock_acquire+0xb9d/0x18b0
> [    6.520487]  dev_vprintk_emit+0x185/0x1ae
> [    6.520494]  ? lock_is_held_type+0xb2/0x110
> [    6.520499]  ? dev_printk_emit+0x4a/0x66
> [    6.520501]  ? mark_held_locks+0x49/0x70
> [    6.520502]  dev_printk_emit+0x4a/0x66
> [    6.520506]  ? preempt_count_sub+0x43/0x50
> [    6.520510]  _dev_info+0x64/0x80
> [    6.520518]  nouveau_fbcon_create+0x2d4/0x500 [nouveau adfaa6c52e612d43880f223e1d4b1d7b83facd58]
> [    6.520615]  __drm_fb_helper_initial_config_and_unlock+0x336/0x5f0 [drm_kms_helper 8e2e6f207f0cb44a547a65ef3965573df1212de6]
> [    6.520635]  nouveau_fbcon_init+0x180/0x1f0 [nouveau adfaa6c52e612d43880f223e1d4b1d7b83facd58]
> [    6.520706]  nouveau_drm_device_init+0x1f7/0x860 [nouveau adfaa6c52e612d43880f223e1d4b1d7b83facd58]
> [    6.520778]  ? pci_update_current_state+0x65/0xa0
> [    6.520785]  nouveau_drm_probe+0x11b/0x220 [nouveau adfaa6c52e612d43880f223e1d4b1d7b83facd58]
> [    6.520856]  local_pci_probe+0x42/0x90
> [    6.520860]  pci_device_probe+0x176/0x240
> [    6.520862]  ? sysfs_do_create_link_sd.isra.2+0x68/0xd0
> [    6.520869]  really_probe+0x108/0x3d0
> [    6.520873]  __driver_probe_device+0x100/0x170
> [    6.520876]  driver_probe_device+0x1f/0xa0
> [    6.520879]  __driver_attach+0xac/0x170
> [    6.520881]  ? __device_attach_driver+0xe0/0xe0
> [    6.520884]  ? __device_attach_driver+0xe0/0xe0
> [    6.520886]  bus_for_each_dev+0x76/0xc0
> [    6.520890]  bus_add_driver+0x19f/0x240
> [    6.520893]  ? 0xffffffffc06ec000
> [    6.520896]  driver_register+0x5b/0xf0
> [    6.520898]  ? 0xffffffffc06ec000
> [    6.520899]  do_one_initcall+0x58/0x3d0
> [    6.520903]  ? trace_kmalloc+0xb6/0x140
> [    6.520905]  ? kmem_cache_alloc_trace+0x13c/0x1c0
> [    6.520907]  ? do_init_module+0x22/0x1fc
> [    6.520914]  do_init_module+0x4b/0x1fc
> [    6.520918]  load_module+0x18d2/0x2380
> [    6.520936]  ? __do_sys_finit_module+0xaf/0x120
> [    6.520937]  __do_sys_finit_module+0xaf/0x120
> [    6.520948]  do_syscall_64+0x58/0x80
> [    6.520951]  ? do_syscall_64+0x67/0x80
> [    6.520953]  ? lockdep_hardirqs_on_prepare+0xd8/0x170
> [    6.520957]  ? do_syscall_64+0x67/0x80
> [    6.520958]  ? do_syscall_64+0x67/0x80
> [    6.520962]  entry_SYSCALL_64_after_hwframe+0x46/0xb0
> [    6.520965] RIP: 0033:0x7f911ee69ec9
> [    6.520967] Code: 2e 00 b8 ca 00 00 00 0f 05 eb a5 66 0f 1f 44 00 00 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 97 7f 2d 00 f7 d8 64 89 01 48
> [    6.520968] RSP: 002b:00007ffe6427de98 EFLAGS: 00000246 ORIG_RAX: 0000000000000139
> [    6.520969] RAX: ffffffffffffffda RBX: 0000558cc2ab38a0 RCX: 00007f911ee69ec9
> [    6.520970] RDX: 0000000000000000 RSI: 00007f911f7dd79d RDI: 000000000000001b
> [    6.520971] RBP: 00007f911f7dd79d R08: 0000000000000000 R09: 0000558cc2a939a0
> [    6.520971] R10: 000000000000001b R11: 0000000000000246 R12: 0000000000020000
> [    6.520972] R13: 0000558cc2abec00 R14: 0000000000000000 R15: 0000558cc2ac7f80

Sebastian