From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1752546AbaIEQVI (ORCPT ); Fri, 5 Sep 2014 12:21:08 -0400 Received: from mail-lb0-f196.google.com ([209.85.217.196]:37115 "EHLO mail-lb0-f196.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751290AbaIEQVF (ORCPT ); Fri, 5 Sep 2014 12:21:05 -0400 Message-ID: <5409E2EB.4080000@gmail.com> Date: Fri, 05 Sep 2014 19:20:59 +0300 From: Kari Suvanto User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:31.0) Gecko/20100101 Thunderbird/31.0 MIME-Version: 1.0 To: "linux-kernel@vger.kernel.org" Subject: INFO: possible irq lock inversion dependency detected Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 7bit Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Hello, I noticed, with next/master tree, this lockdep splat and at least I could not find any discussion about this by googling: [ 33.105722] ========================================================= [ 33.105722] [ INFO: possible irq lock inversion dependency detected ] [ 33.105724] 3.17.0-031700rc3-generic #201409031132 Not tainted [ 33.105724] --------------------------------------------------------- [ 33.105725] swapper/0/0 just changed the state of lock: [ 33.105726] (&(&dev->event_lock)->rlock#2){-.....}, at: [] input_event+0x45/0x70 [ 33.105733] but this lock took another, HARDIRQ-unsafe lock in the past: [ 33.105734] (&(&p->alloc_lock)->rlock){+.+...} [ 33.105734] [ 33.105734] and interrupts could create inverse lock ordering between them. [ 33.105734] [ 33.105736] [ 33.105736] other info that might help us debug this: [ 33.105737] Chain exists of: [ 33.105737] &(&dev->event_lock)->rlock#2 --> &(&client->buffer_lock)->rlock --> &(&p->alloc_lock)->rlock [ 33.105737] [ 33.105740] Possible interrupt unsafe locking scenario: [ 33.105740] [ 33.105740] CPU0 CPU1 [ 33.105741] ---- ---- [ 33.105742] lock(&(&p->alloc_lock)->rlock); [ 33.105743] local_irq_disable(); [ 33.105743] lock(&(&dev->event_lock)->rlock#2); [ 33.105745] lock(&(&client->buffer_lock)->rlock); [ 33.105746] [ 33.105747] lock(&(&dev->event_lock)->rlock#2); [ 33.105748] [ 33.105748] *** DEADLOCK *** [ 33.105748] [ 33.105749] no locks held by swapper/0/0. [ 33.105750] [ 33.105750] the shortest dependencies between 2nd lock and 1st lock: [ 33.105755] -> (&(&p->alloc_lock)->rlock){+.+...} ops: 30838 { [ 33.105757] HARDIRQ-ON-W at: [ 33.105758] [] __lock_acquire+0x538/0xb50 [ 33.105761] [] lock_acquire+0xa9/0x200 [ 33.105763] [] _raw_spin_lock+0x39/0x50 [ 33.105766] [] __set_task_comm+0x2a/0x150 [ 33.105769] [] kthreadd+0x30/0x220 [ 33.105772] [] ret_from_fork+0x7c/0xb0 [ 33.105774] SOFTIRQ-ON-W at: [ 33.105775] [] __lock_acquire+0x2f3/0xb50 [ 33.105776] [] lock_acquire+0xa9/0x200 [ 33.105778] [] _raw_spin_lock+0x39/0x50 [ 33.105780] [] __set_task_comm+0x2a/0x150 [ 33.105782] [] kthreadd+0x30/0x220 [ 33.105783] [] ret_from_fork+0x7c/0xb0 [ 33.105785] INITIAL USE at: [ 33.105786] [] __lock_acquire+0x344/0xb50 [ 33.105787] [] lock_acquire+0xa9/0x200 [ 33.105789] [] _raw_spin_lock+0x39/0x50 [ 33.105791] [] __set_task_comm+0x2a/0x150 [ 33.105792] [] kthreadd+0x30/0x220 [ 33.105794] [] ret_from_fork+0x7c/0xb0 [ 33.105796] } [ 33.105796] ... key at: [] __key.51772+0x0/0x8 [ 33.105799] ... acquired at: [ 33.105799] [] __lock_acquire+0x418/0xb50 [ 33.105801] [] lock_acquire+0xa9/0x200 [ 33.105802] [] _raw_spin_lock+0x39/0x50 [ 33.105804] [] do_prlimit+0x9b/0x200 [ 33.105806] [] SyS_getrlimit+0x2a/0x70 [ 33.105808] [] system_call_fastpath+0x1a/0x1f [ 33.105810] [ 33.105811] -> (tasklist_lock){.+.+..} ops: 26419 { [ 33.105813] HARDIRQ-ON-R at: [ 33.105813] [] __lock_acquire+0x2d1/0xb50 [ 33.105815] [] lock_acquire+0xa9/0x200 [ 33.105817] [] _raw_read_lock+0x3c/0x50 [ 33.105818] [] do_wait+0xb6/0x340 [ 33.105820] [] SyS_wait4+0x64/0xe0 [ 33.105822] [] wait_for_helper+0x4b/0x70 [ 33.105824] [] ret_from_fork+0x7c/0xb0 [ 33.105825] SOFTIRQ-ON-R at: [ 33.105826] [] __lock_acquire+0x2f3/0xb50 [ 33.105828] [] lock_acquire+0xa9/0x200 [ 33.105829] [] _raw_read_lock+0x3c/0x50 [ 33.105831] [] do_wait+0xb6/0x340 [ 33.105833] [] SyS_wait4+0x64/0xe0 [ 33.105834] [] wait_for_helper+0x4b/0x70 [ 33.105836] [] ret_from_fork+0x7c/0xb0 [ 33.105837] INITIAL USE at: [ 33.105838] [] __lock_acquire+0x344/0xb50 [ 33.105840] [] lock_acquire+0xa9/0x200 [ 33.105842] [] _raw_write_lock_irq+0x45/0x60 [ 33.105843] [] copy_process.part.23+0xcf1/0x1e50 [ 33.105846] [] do_fork+0xce/0x750 [ 33.105847] [] kernel_thread+0x26/0x30 [ 33.105849] [] rest_init+0x23/0x140 [ 33.105851] [] start_kernel+0x499/0x4a4 [ 33.105853] [] x86_64_start_reservations+0x2a/0x2c [ 33.105855] [] x86_64_start_kernel+0x143/0x152 [ 33.105857] } [ 33.105858] ... key at: [] tasklist_lock+0x18/0x40 [ 33.105860] ... acquired at: [ 33.105861] [] __lock_acquire+0x418/0xb50 [ 33.105863] [] lock_acquire+0xa9/0x200 [ 33.105864] [] _raw_read_lock+0x3c/0x50 [ 33.105866] [] send_sigio+0x55/0x1d0 [ 33.105868] [] kill_fasync+0xcc/0x2a0 [ 33.105870] [] evdev_pass_values+0xf3/0x1c0 [ 33.105871] [] evdev_events+0x1d3/0x2f0 [ 33.105873] [] input_to_handler+0x97/0xf0 [ 33.105875] [] input_pass_values.part.6+0x2cc/0x370 [ 33.105876] [] input_handle_event+0x121/0x540 [ 33.105878] [] input_inject_event+0x198/0x230 [ 33.105880] [] evdev_write+0x19c/0x220 [ 33.105881] [] vfs_write+0xb7/0x1f0 [ 33.105883] [] SyS_write+0x49/0xb0 [ 33.105884] [] system_call_fastpath+0x1a/0x1f [ 33.105886] [ 33.105887] -> (&f->f_owner.lock){......} ops: 8 { [ 33.105889] INITIAL USE at: [ 33.105890] [] __lock_acquire+0x344/0xb50 [ 33.105891] [] lock_acquire+0xa9/0x200 [ 33.105893] [] _raw_write_lock_irq+0x45/0x60 [ 33.105895] [] __f_setown+0x47/0xe0 [ 33.105896] [] f_setown+0x7d/0x120 [ 33.105897] [] SyS_fcntl+0x341/0x6c0 [ 33.105899] [] system_call_fastpath+0x1a/0x1f [ 33.105901] } [ 33.105901] ... key at: [] __key.31233+0x0/0x8 [ 33.105905] ... acquired at: [ 33.105905] [] __lock_acquire+0x418/0xb50 [ 33.105907] [] lock_acquire+0xa9/0x200 [ 33.105908] [] _raw_read_lock+0x3c/0x50 [ 33.105910] [] send_sigio+0x2a/0x1d0 [ 33.105911] [] kill_fasync+0xcc/0x2a0 [ 33.105913] [] evdev_pass_values+0xf3/0x1c0 [ 33.105914] [] evdev_events+0x1d3/0x2f0 [ 33.105916] [] input_to_handler+0x97/0xf0 [ 33.105918] [] input_pass_values.part.6+0x2cc/0x370 [ 33.105919] [] input_handle_event+0x121/0x540 [ 33.105921] [] input_inject_event+0x198/0x230 [ 33.105922] [] evdev_write+0x19c/0x220 [ 33.105924] [] vfs_write+0xb7/0x1f0 [ 33.105925] [] SyS_write+0x49/0xb0 [ 33.105926] [] system_call_fastpath+0x1a/0x1f [ 33.105928] [ 33.105928] -> (&(&new->fa_lock)->rlock){......} ops: 1 { [ 33.105930] INITIAL USE at: [ 33.105931] [] __lock_acquire+0x344/0xb50 [ 33.105933] [] lock_acquire+0xa9/0x200 [ 33.105934] [] _raw_spin_lock_irqsave+0x51/0x70 [ 33.105936] [] kill_fasync+0x9e/0x2a0 [ 33.105938] [] evdev_pass_values+0xf3/0x1c0 [ 33.105939] [] evdev_events+0x1d3/0x2f0 [ 33.105941] [] input_to_handler+0x97/0xf0 [ 33.105942] [] input_pass_values.part.6+0x2cc/0x370 [ 33.105944] [] input_handle_event+0x121/0x540 [ 33.105946] [] input_inject_event+0x198/0x230 [ 33.105947] [] evdev_write+0x19c/0x220 [ 33.105949] [] vfs_write+0xb7/0x1f0 [ 33.105950] [] SyS_write+0x49/0xb0 [ 33.105951] [] system_call_fastpath+0x1a/0x1f [ 33.105953] } [ 33.105953] ... key at: [] __key.36822+0x0/0x8 [ 33.105955] ... acquired at: [ 33.105956] [] __lock_acquire+0x418/0xb50 [ 33.105957] [] lock_acquire+0xa9/0x200 [ 33.105959] [] mutex_lock_nested+0x6b/0x4e0 [ 33.105960] [] kernfs_fop_open+0x16e/0x360 [ 33.105963] [] do_dentry_open+0x1ff/0x350 [ 33.105965] [] finish_open+0x40/0x50 [ 33.105967] [] do_last+0xc0a/0x13c0 [ 33.105968] [] path_openat+0xbb/0x680 [ 33.105970] [] do_filp_open+0x3a/0x90 [ 33.105971] [] do_sys_open+0x128/0x220 [ 33.105973] [] SyS_open+0x1e/0x20 [ 33.105974] [] system_call_fastpath+0x1a/0x1f [ 33.105976] [ 33.105977] -> (&(&client->buffer_lock)->rlock){......} ops: 15 { [ 33.105979] INITIAL USE at: [ 33.105980] [] __lock_acquire+0x344/0xb50 [ 33.105981] [] lock_acquire+0xa9/0x200 [ 33.105983] [] _raw_spin_lock+0x39/0x50 [ 33.105984] [] evdev_pass_values+0x63/0x1c0 [ 33.105986] [] evdev_events+0x1d3/0x2f0 [ 33.105988] [] input_to_handler+0x97/0xf0 [ 33.105989] [] input_pass_values.part.6+0x2cc/0x370 [ 33.105991] [] input_handle_event+0x121/0x540 [ 33.105992] [] input_event+0x59/0x70 [ 33.105994] [] snd_jack_report+0xd0/0xe0 [snd] [ 33.106000] [] snd_hda_jack_report_sync+0xd8/0xe0 [snd_hda_codec] [ 33.106006] [] jack_callback+0x82/0x90 [snd_hda_codec_hdmi] [ 33.106008] [] hdmi_unsol_event+0xab/0x140 [snd_hda_codec_hdmi] [ 33.106010] [] process_unsol_events+0x67/0x80 [snd_hda_codec] [ 33.106013] [] process_one_work+0x1e3/0x650 [ 33.106014] [] worker_thread+0x121/0x490 [ 33.106015] [] kthread+0xfc/0x120 [ 33.106017] [] ret_from_fork+0x7c/0xb0 [ 33.106019] } [ 33.106020] ... key at: [] __key.29718+0x0/0x8 [ 33.106022] ... acquired at: [ 33.106023] [] __lock_acquire+0x418/0xb50 [ 33.106025] [] lock_acquire+0xa9/0x200 [ 33.106026] [] mutex_lock_nested+0x6b/0x4e0 [ 33.106028] [] kernfs_fop_open+0x16e/0x360 [ 33.106029] [] do_dentry_open+0x1ff/0x350 [ 33.106031] [] finish_open+0x40/0x50 [ 33.106033] [] do_last+0xc0a/0x13c0 [ 33.106034] [] path_openat+0xbb/0x680 [ 33.106035] [] do_filp_open+0x3a/0x90 [ 33.106036] [] do_sys_open+0x128/0x220 [ 33.106038] [] SyS_open+0x1e/0x20 [ 33.106040] [] system_call_fastpath+0x1a/0x1f [ 33.106041] [ 33.106042] -> (&(&dev->event_lock)->rlock#2){-.....} ops: 176 { [ 33.106044] IN-HARDIRQ-W at: [ 33.106045] [] __lock_acquire+0x66d/0xb50 [ 33.106047] [] lock_acquire+0xa9/0x200 [ 33.106048] [] _raw_spin_lock_irqsave+0x51/0x70 [ 33.106050] [] input_event+0x45/0x70 [ 33.106052] [] hidinput_report_event+0x3f/0x50 [hid] [ 33.106054] [] hid_report_raw_event+0x148/0x1c0 [hid] [ 33.106057] [] hid_input_report+0x112/0x190 [hid] [ 33.106059] [] hid_irq_in+0x8c/0x210 [usbhid] [ 33.106061] [] __usb_hcd_giveback_urb+0x83/0x130 [ 33.106063] [] usb_hcd_giveback_urb+0x3f/0x140 [ 33.106065] [] handle_tx_event+0x22f/0x12b0 [ 33.106068] [] xhci_irq+0x2b6/0xa60 [ 33.106069] [] xhci_msi_irq+0x11/0x20 [ 33.106071] [] handle_irq_event_percpu+0x3e/0x340 [ 33.106073] [] handle_irq_event+0x3d/0x60 [ 33.106075] [] handle_edge_irq+0x7f/0x120 [ 33.106076] [] handle_irq+0x1e/0x30 [ 33.106079] [] do_IRQ+0x4f/0xf0 [ 33.106081] [] ret_from_intr+0x0/0x1a [ 33.106082] [] cpuidle_enter+0x17/0x20 [ 33.106084] [] cpu_idle_loop+0x401/0x4e0 [ 33.106086] [] cpu_startup_entry+0x5b/0x60 [ 33.106087] [] rest_init+0x13a/0x140 [ 33.106088] [] start_kernel+0x499/0x4a4 [ 33.106090] [] x86_64_start_reservations+0x2a/0x2c [ 33.106092] [] x86_64_start_kernel+0x143/0x152 [ 33.106094] INITIAL USE at: [ 33.106094] [] __lock_acquire+0x344/0xb50 [ 33.106096] [] lock_acquire+0xa9/0x200 [ 33.106098] [] _raw_spin_lock_irqsave+0x51/0x70 [ 33.106099] [] input_event+0x45/0x70 [ 33.106101] [] snd_jack_report+0xbb/0xe0 [snd] [ 33.106105] [] __snd_hda_jack_add_kctl+0x151/0x160 [snd_hda_codec] [ 33.106109] [] snd_hda_jack_add_kctl+0x14/0x20 [snd_hda_codec] [ 33.106112] [] generic_hdmi_build_jack+0xd4/0x150 [snd_hda_codec_hdmi] [ 33.106114] [] generic_hdmi_build_controls+0x46/0x210 [snd_hda_codec_hdmi] [ 33.106116] [] snd_hda_codec_build_controls+0x1c5/0x220 [snd_hda_codec] [ 33.106120] [] snd_hda_build_controls+0x43/0xa0 [snd_hda_codec] [ 33.106123] [] azx_mixer_create+0x15/0x20 [snd_hda_controller] [ 33.106125] [] azx_probe_continue+0x361/0x710 [snd_hda_intel] [ 33.106127] [] azx_probe_work+0x15/0x20 [snd_hda_intel] [ 33.106129] [] process_one_work+0x1e3/0x650 [ 33.106130] [] worker_thread+0x121/0x490 [ 33.106132] [] kthread+0xfc/0x120 [ 33.106134] [] ret_from_fork+0x7c/0xb0 [ 33.106135] } [ 33.106136] ... key at: [] __key.28093+0x0/0x8 [ 33.106138] ... acquired at: [ 33.106138] [] check_usage_forwards+0x17a/0x180 [ 33.106140] [] mark_lock+0x1a1/0x2a0 [ 33.106141] [] __lock_acquire+0x66d/0xb50 [ 33.106143] [] lock_acquire+0xa9/0x200 [ 33.106145] [] _raw_spin_lock_irqsave+0x51/0x70 [ 33.106146] [] input_event+0x45/0x70 [ 33.106148] [] hidinput_report_event+0x3f/0x50 [hid] [ 33.106151] [] hid_report_raw_event+0x148/0x1c0 [hid] [ 33.106153] [] hid_input_report+0x112/0x190 [hid] [ 33.106155] [] hid_irq_in+0x8c/0x210 [usbhid] [ 33.106157] [] __usb_hcd_giveback_urb+0x83/0x130 [ 33.106159] [] usb_hcd_giveback_urb+0x3f/0x140 [ 33.106160] [] handle_tx_event+0x22f/0x12b0 [ 33.106162] [] xhci_irq+0x2b6/0xa60 [ 33.106164] [] xhci_msi_irq+0x11/0x20 [ 33.106165] [] handle_irq_event_percpu+0x3e/0x340 [ 33.106167] [] handle_irq_event+0x3d/0x60 [ 33.106169] [] handle_edge_irq+0x7f/0x120 [ 33.106170] [] handle_irq+0x1e/0x30 [ 33.106172] [] do_IRQ+0x4f/0xf0 [ 33.106174] [] ret_from_intr+0x0/0x1a [ 33.106175] [] cpuidle_enter+0x17/0x20 [ 33.106177] [] cpu_idle_loop+0x401/0x4e0 [ 33.106178] [] cpu_startup_entry+0x5b/0x60 [ 33.106179] [] rest_init+0x13a/0x140 [ 33.106181] [] start_kernel+0x499/0x4a4 [ 33.106182] [] x86_64_start_reservations+0x2a/0x2c [ 33.106184] [] x86_64_start_kernel+0x143/0x152 [ 33.106185] [ 33.106186] [ 33.106186] stack backtrace: [ 33.106188] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 3.17.0-031700rc3-generic #201409031132 [ 33.106189] Hardware name: MSI MS-7924/Z97M-G43(MS-7924), BIOS V1.5 07/22/2014 [ 33.106190] ffffffff81e1d4c0 ffff88041ba03a60 ffffffff81829c6a ffffffff82bd7620 [ 33.106192] ffff88041ba03aa0 ffffffff81822ff3 ffffffff81cbcf5e 0000000000000000 [ 33.106193] ffffffff81e1dd58 ffffffff81e1d4c0 ffffffff81cbcf5e ffffffff82bd7620 [ 33.106195] Call Trace: [ 33.106196] [] dump_stack+0x4d/0x66 [ 33.106200] [] print_irq_inversion_bug.part.38+0x1ac/0x1b8 [ 33.106203] [] check_usage_forwards+0x17a/0x180 [ 33.106205] [] ? save_stack_trace+0x2b/0x50 [ 33.106206] [] ? check_usage_backwards+0x180/0x180 [ 33.106208] [] mark_lock+0x1a1/0x2a0 [ 33.106210] [] __lock_acquire+0x66d/0xb50 [ 33.106212] [] ? hiddev_send_event.isra.3+0xe6/0x100 [usbhid] [ 33.106214] [] lock_acquire+0xa9/0x200 [ 33.106216] [] ? input_event+0x45/0x70 [ 33.106218] [] _raw_spin_lock_irqsave+0x51/0x70 [ 33.106219] [] ? input_event+0x45/0x70 [ 33.106221] [] input_event+0x45/0x70 [ 33.106224] [] hidinput_report_event+0x3f/0x50 [hid] [ 33.106226] [] hid_report_raw_event+0x148/0x1c0 [hid] [ 33.106228] [] ? _raw_spin_unlock_irqrestore+0x5f/0x70 [ 33.106230] [] hid_input_report+0x112/0x190 [hid] [ 33.106232] [] hid_irq_in+0x8c/0x210 [usbhid] [ 33.106234] [] __usb_hcd_giveback_urb+0x83/0x130 [ 33.106236] [] usb_hcd_giveback_urb+0x3f/0x140 [ 33.106238] [] handle_tx_event+0x22f/0x12b0 [ 33.106240] [] ? xhci_irq+0x2c/0xa60 [ 33.106241] [] xhci_irq+0x2b6/0xa60 [ 33.106243] [] xhci_msi_irq+0x11/0x20 [ 33.106245] [] handle_irq_event_percpu+0x3e/0x340 [ 33.106247] [] handle_irq_event+0x3d/0x60 [ 33.106249] [] handle_edge_irq+0x7f/0x120 [ 33.106251] [] handle_irq+0x1e/0x30 [ 33.106253] [] do_IRQ+0x4f/0xf0 [ 33.106254] [] common_interrupt+0x72/0x72 [ 33.106255] [] ? cpuidle_enter_state+0x75/0x300 [ 33.106258] [] cpuidle_enter+0x17/0x20 [ 33.106260] [] cpu_idle_loop+0x401/0x4e0 [ 33.106261] [] cpu_startup_entry+0x5b/0x60 [ 33.106262] [] rest_init+0x13a/0x140 [ 33.106264] [] ? rest_init+0x5/0x140 [ 33.106266] [] start_kernel+0x499/0x4a4 [ 33.106267] [] ? set_init_arg+0x53/0x53 [ 33.106269] [] ? early_idt_handlers+0x120/0x120 [ 33.106271] [] x86_64_start_reservations+0x2a/0x2c [ 33.106272] [] x86_64_start_kernel+0x143/0x152 I have fixed lockdep discussed here: https://lkml.org/lkml/2014/8/25/515 but as I'm not sure if my fix was any good I also tried to revert commit causing that and still I see this. I have not tried bisecting yet but tried to check if anything has changed around those locks recently but did not spot anything obvious yet. -Kari