From mboxrd@z Thu Jan 1 00:00:00 1970 From: Imre Deak Subject: snd_hda_intel/snd_hda_codec_hdmi module load/unload race Date: Wed, 14 Dec 2016 23:00:50 +0200 Message-ID: <1481749250.8172.5.camel@intel.com> Reply-To: imre.deak@intel.com Mime-Version: 1.0 Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: 7bit Return-path: Received: from mga06.intel.com (mga06.intel.com [134.134.136.31]) by alsa0.perex.cz (Postfix) with ESMTP id BAFF7267064 for ; Wed, 14 Dec 2016 22:01:06 +0100 (CET) List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: alsa-devel-bounces@alsa-project.org Sender: alsa-devel-bounces@alsa-project.org To: alsa-devel , Takashi Iwai List-Id: alsa-devel@alsa-project.org Hi, I got the trace below while trying to unload (unbind) snd_hda_intel, while its still loading the HDMI codec driver. IIUC what happens is: Task1 Task2 Task3 modprobe snd_hda_intel schedule(azx_probe_work) unbind snd_hda_intel via sysfs device_release_driver() device_lock(snd_hda_intel) azx_remove() cancel_work_sync(azx_probe_work) azx_probe_work() request_module(snd-hda-codec-hdmi) hdmi_driver_init() __driver_attach() device_lock(snd_hda_intel) Deadlock, since azx_probe_work() will never finish and the snd_hda_intel device lock will never get released. --Imre [ 246.805268] INFO: task drv_module_relo:1684 blocked for more than 120 seconds. [ 246.805834] Tainted: G W 4.9.0-CI-CI_DRM_1946+ #158 [ 246.806284] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 246.806779] drv_module_relo D 0 1684 1597 0x00000000 [ 246.807171] ffff8802703cbac0 ffff8802643926c0 000000000000479d ffff8802713b0040 [ 246.807706] ffff88027fc98118 ffffc90003cffa58 ffffffff8181d429 0000000000000046 [ 246.808217] ffffffff827d2470 0000000000000001 ffff88027fc98118 ffff88027fc98100 [ 246.808739] Call Trace: [ 246.808945] [] ? __schedule+0x2c9/0xa30 [ 246.809281] [] schedule+0x3b/0x90 [ 246.809618] [] schedule_timeout+0x25b/0x4c0 [ 246.810021] [] ? mark_held_locks+0x6f/0xa0 [ 246.810370] [] ? _raw_spin_unlock_irq+0x27/0x50 [ 246.810759] [] ? trace_hardirqs_on_caller+0x122/0x1b0 [ 246.811963] [] wait_for_common+0xf0/0x160 [ 246.812463] [] ? wake_up_q+0x70/0x70 [ 246.812795] [] wait_for_completion+0x18/0x20 [ 246.813389] [] flush_work+0x203/0x2e0 [ 246.813714] [] ? flush_work+0x2a6/0x2e0 [ 246.814088] [] ? flush_workqueue_prep_pwqs+0x220/0x220 [ 246.814790] [] __cancel_work_timer+0x110/0x1d0 [ 246.815346] [] ? trace_hardirqs_on_caller+0x122/0x1b0 [ 246.815742] [] ? trace_hardirqs_on+0xd/0x10 [ 246.816096] [] cancel_work_sync+0xb/0x10 [ 246.816566] [] azx_remove+0x24/0x30 [snd_hda_intel] [ 246.816956] [] pci_device_remove+0x34/0xb0 [ 246.817373] [] __device_release_driver+0x9c/0x150 [ 246.817717] [] device_release_driver+0x20/0x30 [ 246.818077] [] unbind_store+0x10a/0x150 [ 246.818549] [] drv_attr_store+0x20/0x30 [ 246.818885] [] sysfs_kf_write+0x40/0x50 [ 246.819290] [] kernfs_fop_write+0x130/0x1b0 [ 246.819639] [] __vfs_write+0x23/0x120 [ 246.819963] [] ? rcu_read_lock_sched_held+0x70/0x80 [ 246.820476] [] ? rcu_sync_lockdep_assert+0x2a/0x50 [ 246.820859] [] ? __sb_start_write+0xf8/0x200 [ 246.821292] [] ? vfs_write+0x169/0x1b0 [ 246.821597] [] vfs_write+0xb3/0x1b0 [ 246.821907] [] ? trace_hardirqs_on_caller+0x122/0x1b0 [ 246.822405] [] SyS_write+0x44/0xb0 [ 246.822684] [] entry_SYSCALL_64_fastpath+0x1c/0xb1 [ 246.823064] Showing all locks held in the system: [ 246.823568] 2 locks held by kworker/u8:0/6: [ 246.823817] #0: ("events_unbound"){.+.+.+}, at: [] process_one_work+0x166/0x6b0 [ 246.824400] #1: ((&sub_info->work)){+.+.+.}, at: [] process_one_work+0x166/0x6b0 [ 246.824940] 2 locks held by khungtaskd/34: [ 246.825210] #0: (rcu_read_lock){......}, at: [] watchdog+0x9c/0x600 [ 246.825726] #1: (tasklist_lock){.+.+..}, at: [] debug_show_all_locks+0x3d/0x1a0 [ 246.826303] 2 locks held by kworker/3:1/50: [ 246.826535] #0: ("events"){++++.+}, at: [] process_one_work+0x166/0x6b0 [ 246.827104] #1: ((&hda->probe_work)){+.+.+.}, at: [] process_one_work+0x166/0x6b0 [ 246.827706] 5 locks held by drv_module_relo/1684: [ 246.827963] #0: (sb_writers#6){.+.+.+}, at: [] vfs_write+0x169/0x1b0 [ 246.828507] #1: (&of->mutex){+.+.+.}, at: [] kernfs_fop_write+0xfc/0x1b0 [ 246.829083] #2: (s_active#186){++++.+}, at: [] kernfs_fop_write+0x104/0x1b0 [ 246.829663] #3: (&dev->mutex){......}, at: [] unbind_store+0xfa/0x150 [ 246.830204] #4: (&dev->mutex){......}, at: [] device_release_driver+0x18/0x30 [ 246.830772] 1 lock held by modprobe/1685: [ 246.830992] #0: (&dev->mutex){......}, at: [] __driver_attach+0x5a/0xe0 [ 246.831575] 2 locks held by bash/1727: [ 246.831782] #0: (&tty->ldisc_sem){++++.+}, at: [] ldsem_down_read+0x2d/0x40 [ 246.832344] #1: (&ldata->atomic_read_lock){+.+...}, at: [] n_tty_read+0xa9/0x880 [ 246.833050] ============================================= [ 246.833436] INFO: task modprobe:1685 blocked for more than 120 seconds. [ 246.833829] Tainted: G W 4.9.0-CI-CI_DRM_1946+ #158 [ 246.834221] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 246.834680] modprobe D 0 1685 6 0x00000000 [ 246.835029] ffff8802703c9a40 ffff8802760e4d40 00000000000091ba ffff8802559e26c0 [ 246.835522] ffff88027fd18118 ffffc900032bbb70 ffffffff8181d429 0000000000000000 [ 246.835967] ffffc900032bbb98 0000000000000292 ffff88027fd18118 ffff88027fd18100 [ 246.836462] Call Trace: [ 246.836628] [] ? __schedule+0x2c9/0xa30 [ 246.836924] [] schedule+0x3b/0x90 [ 246.837243] [] schedule_preempt_disabled+0x13/0x20 [ 246.837629] [] mutex_lock_nested+0x16c/0x400 [ 246.837946] [] ? __driver_attach+0x5a/0xe0 [ 246.838298] [] ? driver_probe_device+0x430/0x430 [ 246.838676] [] __driver_attach+0x5a/0xe0 [ 246.839008] [] ? driver_probe_device+0x430/0x430 [ 246.839354] [] bus_for_each_dev+0x61/0xa0 [ 246.839704] [] driver_attach+0x19/0x20 [ 246.840029] [] bus_add_driver+0x1fb/0x270 [ 246.840346] [] ? 0xffffffffa014a000 [ 246.840645] [] driver_register+0x5b/0xd0 [ 246.840977] [] __hda_codec_driver_register+0x55/0x60 [snd_hda_codec] [ 246.841417] [] hdmi_driver_init+0x1e/0x20 [snd_hda_codec_hdmi] [ 246.841861] [] do_one_initcall+0x38/0x150 [ 246.842177] [] ? rcu_read_lock_sched_held+0x70/0x80 [ 246.842566] [] ? kmem_cache_alloc_trace+0x274/0x2e0 [ 246.842951] [] ? do_init_module+0x22/0x1d1 [ 246.843307] [] do_init_module+0x5a/0x1d1 [ 246.843617] [] load_module+0x2275/0x27d0 [ 246.843951] [] ? symbol_put_addr+0x60/0x60 [ 246.844306] [] ? kernel_read_file+0x105/0x190 [ 246.844637] [] SyS_finit_module+0xbc/0xf0 [ 246.844979] [] entry_SYSCALL_64_fastpath+0x1c/0xb1 [ 246.845368] Showing all locks held in the system: [ 246.845745] 2 locks held by kworker/u8:0/6: [ 246.845974] #0: ("events_unbound"){.+.+.+}, at: [] process_one_work+0x166/0x6b0 [ 246.846553] #1: ((&sub_info->work)){+.+.+.}, at: [] process_one_work+0x166/0x6b0 [ 246.847133] 2 locks held by khungtaskd/34: [ 246.847399] #0: (rcu_read_lock){......}, at: [] watchdog+0x9c/0x600 [ 246.847913] #1: (tasklist_lock){.+.+..}, at: [] debug_show_all_locks+0x3d/0x1a0 [ 246.848488] 2 locks held by kworker/3:1/50: [ 246.848747] #0: ("events"){++++.+}, at: [] process_one_work+0x166/0x6b0 [ 246.849286] #1: ((&hda->probe_work)){+.+.+.}, at: [] process_one_work+0x166/0x6b0 [ 246.849875] 1 lock held by in:imklog/491: [ 246.850094] #0: (&f->f_pos_lock){+.+.+.}, at: [] __fdget_pos+0x3e/0x50 [ 246.850657] 5 locks held by drv_module_relo/1684: [ 246.850931] #0: (sb_writers#6){.+.+.+}, at: [] vfs_write+0x169/0x1b0 [ 246.851474] #1: (&of->mutex){+.+.+.}, at: [] kernfs_fop_write+0xfc/0x1b0 [ 246.852013] #2: (s_active#186){++++.+}, at: [] kernfs_fop_write+0x104/0x1b0 [ 246.852577] #3: (&dev->mutex){......}, at: [] unbind_store+0xfa/0x150 [ 246.853103] #4: (&dev->mutex){......}, at: [] device_release_driver+0x18/0x30 [ 246.853714] 1 lock held by modprobe/1685: [ 246.853934] #0: (&dev->mutex){......}, at: [] __driver_attach+0x5a/0xe0 [ 246.854473] 2 locks held by bash/1727: [ 246.854713] #0: (&tty->ldisc_sem){++++.+}, at: [] ldsem_down_read+0x2d/0x40 [ 246.855272] #1: (&ldata->atomic_read_lock){+.+...}, at: [] n_tty_read+0xa9/0x880 Stack trace of kworker/50: [] call_usermodehelper_exec+0x133/0x1d0 [] __request_module+0x18f/0x360 [] request_codec_module+0x52/0x60 [snd_hda_codec] [] snd_hda_codec_configure+0x5d/0x170 [snd_hda_codec] [] azx_codec_configure+0x23/0x40 [snd_hda_codec] [] azx_probe_work+0x5d0/0x8d0 [snd_hda_intel] [] process_one_work+0x1ec/0x6b0 [] worker_thread+0x49/0x490 [] kthread+0xeb/0x110 [] ret_from_fork+0x27/0x40 [] 0xffffffffffffffff