On Wed 2018-08-08 11:05:00, Vlastimil Babka wrote: > On 08/08/2018 11:01 AM, Vlastimil Babka wrote: > > fbcon_startup() calls kzalloc(sizeof(struct fbcon_ops), GFP_KERNEL) so > > it tells slab it can sleep. The problem must be higher in the stack, > > CCing printk people. > > Uh just noticed there was also attached dmesg which my reply converted > to inline. The first problem there is a lockdep splat. The lockdep splat might eventually be a valid issue (recursive lock) in the networking code. But it seems to be unrelated to the later problems with sleeping in fbcon_startup(). Adding networking people into CC. Please, find below the relevant part from the dmesg. The full log can be found in the original message at https://marc.info/?l=linux-mm&m=153370024009996&w=2 Lock recursion in bluetooth code: [ 32.050660] Bluetooth: RFCOMM TTY layer initialized [ 32.050675] Bluetooth: RFCOMM socket layer initialized [ 32.050719] Bluetooth: RFCOMM ver 1.11 [ 34.413359] fuse init (API version 7.27) [ 40.562871] rfkill: input handler disabled [ 42.272301] pool (2344) used greatest stack depth: 11320 bytes left [ 42.701283] ISO 9660 Extensions: Microsoft Joliet Level 3 [ 42.704062] ISO 9660 Extensions: Microsoft Joliet Level 3 [ 42.710375] ISO 9660 Extensions: RRIP_1991A [ 64.930766] tracker-extract (2229) used greatest stack depth: 11176 bytes left [ 465.911281] TaskSchedulerFo (3362) used greatest stack depth: 11112 bytes left [ 491.743600] TaskSchedulerFo (3364) used greatest stack depth: 11032 bytes left [ 507.733884] nf_conntrack: default automatic helper assignment has been turned off \ for security reasons and CT-based firewall rule not found. Use the iptables CT \ target to attach helpers instead. [ 660.384586] kworker/dying (155) used greatest \ stack depth: 10888 bytes left [ 699.910094] device enp2s0 entered promiscuous mode [ 1098.658964] kworker/dying (7) used greatest stack depth: 10712 bytes left [ 1843.488301] perf: interrupt took too long (2510 > 2500), lowering \ kernel.perf_event_max_sample_rate to 79000 [ 2819.896469] perf: interrupt took too \ long (3138 > 3137), lowering kernel.perf_event_max_sample_rate to 63000 [ \ 6120.247124] perf: interrupt took too long (3923 > 3922), lowering \ kernel.perf_event_max_sample_rate to 50000 [ 6829.212232] ============================================ [ 6829.212234] WARNING: possible recursive locking detected [ 6829.212236] 4.18.0-0.rc7.git1.1.fc29.x86_64 #1 Not tainted [ 6829.212237] -------------------------------------------- [ 6829.212239] kworker/u17:2/28441 is trying to acquire lock: [ 6829.212242] 000000004025b723 (sk_lock-AF_BLUETOOTH-BTPROTO_L2CAP){+.+.}, at: \ bt_accept_enqueue+0x3c/0xb0 [bluetooth] [ 6829.212260] but task is already holding lock: [ 6829.212262] 000000004cb71eef (sk_lock-AF_BLUETOOTH-BTPROTO_L2CAP){+.+.}, at: \ l2cap_sock_new_connection_cb+0x18/0xa0 [bluetooth] [ 6829.212278] other info that might help us debug this: [ 6829.212279] Possible unsafe locking scenario: [ 6829.212281] CPU0 [ 6829.212282] ---- [ 6829.212284] lock(sk_lock-AF_BLUETOOTH-BTPROTO_L2CAP); [ 6829.212286] lock(sk_lock-AF_BLUETOOTH-BTPROTO_L2CAP); [ 6829.212288] *** DEADLOCK *** [ 6829.212290] May be due to missing lock nesting notation [ 6829.212293] 5 locks held by kworker/u17:2/28441: [ 6829.212294] #0: 000000009af6a4dc ((wq_completion)"%s"hdev->name#2){+.+.}, at: \ process_one_work+0x1f3/0x650 [ 6829.212301] #1: 000000006f7488f4 \ ((work_completion)(&hdev->rx_work)){+.+.}, at: process_one_work+0x1f3/0x650 [ \ 6829.212306] #2: 000000003dba8333 (&conn->chan_lock){+.+.}, at: \ l2cap_connect+0x8f/0x5a0 [bluetooth] [ 6829.212321] #3: 00000000aaa813b9 \ (&chan->lock/2){+.+.}, at: l2cap_connect+0xa9/0x5a0 [bluetooth] [ 6829.212335] #4: \ 000000004cb71eef (sk_lock-AF_BLUETOOTH-BTPROTO_L2CAP){+.+.}, at: \ l2cap_sock_new_connection_cb+0x18/0xa0 [bluetooth] [ 6829.212350] stack backtrace: [ 6829.212354] CPU: 6 PID: 28441 Comm: kworker/u17:2 Not tainted \ 4.18.0-0.rc7.git1.1.fc29.x86_64 #1 [ 6829.212355] Hardware name: Gigabyte Technology \ Co., Ltd. Z87M-D3H/Z87M-D3H, BIOS F11 08/12/2014 [ 6829.212365] Workqueue: hci0 \ hci_rx_work [bluetooth] [ 6829.212367] Call Trace: [ 6829.212373] dump_stack+0x85/0xc0 [ 6829.212377] __lock_acquire.cold.64+0x158/0x227 [ 6829.212381] ? mark_held_locks+0x57/0x80 [ 6829.212384] lock_acquire+0x9e/0x1b0 [ 6829.212394] ? bt_accept_enqueue+0x3c/0xb0 [bluetooth] [ 6829.212398] lock_sock_nested+0x72/0xa0 [ 6829.212407] ? bt_accept_enqueue+0x3c/0xb0 [bluetooth] [ 6829.212417] bt_accept_enqueue+0x3c/0xb0 [bluetooth] [ 6829.212429] l2cap_sock_new_connection_cb+0x5d/0xa0 [bluetooth] [ 6829.212441] l2cap_connect+0x110/0x5a0 [bluetooth] [ 6829.212454] ? l2cap_recv_frame+0x6d0/0x2cb0 [bluetooth] [ 6829.212458] ? __mutex_unlock_slowpath+0x4b/0x2b0 [ 6829.212470] l2cap_recv_frame+0x6e8/0x2cb0 [bluetooth] [ 6829.212474] ? __mutex_unlock_slowpath+0x4b/0x2b0 [ 6829.212484] hci_rx_work+0x1c6/0x5d0 [bluetooth] [ 6829.212488] process_one_work+0x27d/0x650 [ 6829.212492] worker_thread+0x3c/0x390 [ 6829.212494] ? process_one_work+0x650/0x650 [ 6829.212498] kthread+0x120/0x140 [ 6829.212501] ? kthread_create_worker_on_cpu+0x70/0x70 [ 6829.212504] ret_from_fork+0x3a/0x50 [ 6829.285343] BUG: sleeping function called from invalid context at \ net/core/sock.c:2833 [ 6829.285349] in_atomic(): 1, irqs_disabled(): 0, pid: 1743, \ name: krfcommd [ 6829.285351] INFO: lockdep is turned off. [ 6829.285355] CPU: 6 PID: 1743 Comm: krfcommd Not tainted \ 4.18.0-0.rc7.git1.1.fc29.x86_64 #1 [ 6829.285358] Hardware name: Gigabyte Technology \ Co., Ltd. Z87M-D3H/Z87M-D3H, BIOS F11 08/12/2014 [ 6829.285360] Call Trace: [ 6829.285368] dump_stack+0x85/0xc0 [ 6829.285373] ___might_sleep.cold.72+0xac/0xbc [ 6829.285378] lock_sock_nested+0x29/0xa0 [ 6829.285394] bt_accept_enqueue+0x3c/0xb0 [bluetooth] [ 6829.285401] rfcomm_connect_ind+0x21b/0x260 [rfcomm] [ 6829.285406] rfcomm_run+0x1611/0x1820 [rfcomm] [ 6829.285411] ? do_wait_intr_irq+0xb0/0xb0 [ 6829.285416] ? rfcomm_check_accept+0x90/0x90 [rfcomm] [ 6829.285419] kthread+0x120/0x140 [ 6829.285422] ? kthread_create_worker_on_cpu+0x70/0x70 [ 6829.285426] ret_from_fork+0x3a/0x50 [ 6829.476282] input: 04:5D:4B:5F:34:57 as /devices/virtual/input/input35 [ 7273.090391] show_signal_msg: 23 callbacks suppressed [ 7273.090393] CFileWriterThre[29422]: segfault at 7f078bfe7240 ip 00007f079137843c \ sp 00007f078bb8dcf0 error 4 in steamclient.so[7f0790880000+14d2000] [ 7273.090404] \ Code: 89 df ff d2 8b 45 00 83 f8 02 0f 84 9e 00 00 00 83 f8 03 0f 84 55 05 00 00 83 \ f8 01 74 48 31 ed 4d 85 e4 74 11 48 85 db 74 0c <48> 8b 03 4c 89 e6 48 89 df ff 50 10 \ 48 8b b4 24 e8 00 00 00 64 48 [ 7755.656023] rfkill: input handler enabled [ 7773.439895] rfkill: input handler disabled [ 8075.232946] BUG: sleeping function called from invalid context at \ net/core/sock.c:2833 [ 8075.232951] in_atomic(): 1, irqs_disabled(): 0, pid: 1743, \ name: krfcommd [ 8075.232952] INFO: lockdep is turned off. [ 8075.232956] CPU: 5 PID: 1743 Comm: krfcommd Tainted: G W \ 4.18.0-0.rc7.git1.1.fc29.x86_64 #1 [ 8075.232957] Hardware name: Gigabyte Technology \ Co., Ltd. Z87M-D3H/Z87M-D3H, BIOS F11 08/12/2014 [ 8075.232959] Call Trace: [ 8075.232965] dump_stack+0x85/0xc0 [ 8075.232969] ___might_sleep.cold.72+0xac/0xbc [ 8075.232973] lock_sock_nested+0x29/0xa0 [ 8075.232987] bt_accept_enqueue+0x3c/0xb0 [bluetooth] [ 8075.232992] rfcomm_connect_ind+0x21b/0x260 [rfcomm] [ 8075.232997] rfcomm_run+0x1611/0x1820 [rfcomm] [ 8075.233001] ? do_wait_intr_irq+0xb0/0xb0 [ 8075.233005] ? rfcomm_check_accept+0x90/0x90 [rfcomm] [ 8075.233008] kthread+0x120/0x140 [ 8075.233011] ? kthread_create_worker_on_cpu+0x70/0x70 [ 8075.233014] ret_from_fork+0x3a/0x50 [ 8075.413187] input: 04:5D:4B:5F:34:57 as /devices/virtual/input/input36 [13538.300352] steam[4385]: segfault at 0 ip 00000000eabc32d9 sp 00000000ffdca1b0 \ error 4 in vgui2_s.so[eab26000+292000] [13538.300365] Code: 74 03 00 00 00 00 00 00 \ c7 44 24 08 02 00 00 00 c7 44 24 04 10 00 00 00 c7 04 24 44 ac 00 00 e8 1d 40 fb ff \ 89 86 74 03 00 00 <8b> 00 8b 78 10 e8 3d 1a fb ff 8b 86 74 03 00 00 dd 5c 24 04 89 04 \ [14324.004275] pool[443]: segfault at 0 ip 00007f53e2399556 sp 00007f53ceffcc40 \ error 4 in libnssutil3.so[7f53e2395000+12000] [14324.004286] Code: d8 5b 5d 41 5c c3 \ 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 40 00 f3 0f 1e fa 41 54 41 bc ff ff ff ff 55 53 \ 48 89 fb e8 7a bc ff ff <48> 8b 3b 48 89 c5 e8 9f c1 ff ff 48 8b 43 38 48 39 c5 75 23 \ eb 2d [14324.007764] rfkill: input handler enabled [14348.933385] rfkill: input handler disabled [15930.680376] DMA-API: debugging out of memory - disabling [16087.451698] vaapi-queue:src (10166) used greatest stack depth: 10616 bytes left [19689.192082] BUG: sleeping function called from invalid context at \ net/core/sock.c:2833 [19689.192087] in_atomic(): 1, irqs_disabled(): 0, pid: 1743, \ name: krfcommd [19689.192089] INFO: lockdep is turned off. [19689.192093] CPU: 6 PID: 1743 Comm: krfcommd Tainted: G W \ 4.18.0-0.rc7.git1.1.fc29.x86_64 #1 [19689.192096] Hardware name: Gigabyte Technology \ Co., Ltd. Z87M-D3H/Z87M-D3H, BIOS F11 08/12/2014 [19689.192098] Call Trace: [19689.192106] dump_stack+0x85/0xc0 [19689.192112] ___might_sleep.cold.72+0xac/0xbc [19689.192117] lock_sock_nested+0x29/0xa0 [19689.192142] bt_accept_enqueue+0x3c/0xb0 [bluetooth] [19689.192150] rfcomm_connect_ind+0x21b/0x260 [rfcomm] [19689.192157] rfcomm_run+0x1611/0x1820 [rfcomm] [19689.192163] ? do_wait_intr_irq+0xb0/0xb0 [19689.192179] ? rfcomm_check_accept+0x90/0x90 [rfcomm] [19689.192183] kthread+0x120/0x140 [19689.192186] ? kthread_create_worker_on_cpu+0x70/0x70 [19689.192190] ret_from_fork+0x3a/0x50 [19689.377451] input: 04:5D:4B:5F:34:57 as /devices/virtual/input/input37 Best Regards, Petr
