From mboxrd@z Thu Jan 1 00:00:00 1970 From: linux@arm.linux.org.uk (Russell King - ARM Linux) Date: Thu, 16 Jan 2014 11:46:54 +0000 Subject: Huge lockdep warning from sdhci/imx esdhc code Message-ID: <20140116114654.GU15937@n2100.arm.linux.org.uk> To: linux-arm-kernel@lists.infradead.org List-Id: linux-arm-kernel.lists.infradead.org ====================================================== [ INFO: HARDIRQ-safe -> HARDIRQ-unsafe lock order detected ] 3.13.0-rc7+ #401 Not tainted ------------------------------------------------------ kworker/u8:1/44 [HC0[0]:SC0[0]:HE0:SE1] is trying to acquire: (prepare_lock){+.+.+.}, at: [] clk_prepare_lock+0x80/0xf4 and this task is already holding: (&(&host->lock)->rlock){-.-...}, at: [] sdhci_do_set_ios+0x20/0x740 which would create a new lock dependency: (&(&host->lock)->rlock){-.-...} -> (prepare_lock){+.+.+.} but this new dependency connects a HARDIRQ-irq-safe lock: (&(&host->lock)->rlock){-.-...} ... which became HARDIRQ-irq-safe at: [] mark_lock+0x15c/0x704 [] __lock_acquire+0xb8c/0x1e14 [] lock_acquire+0xa4/0x114 [] _raw_spin_lock+0x34/0x44 [] sdhci_irq+0x20/0xa14 [] handle_irq_event_percpu+0x68/0x254 [] handle_irq_event+0x44/0x64 [] handle_fasteoi_irq+0xac/0x180 [] generic_handle_irq+0x28/0x38 [] handle_IRQ+0x40/0x98 [] gic_handle_irq+0x30/0x64 [] __irq_svc+0x44/0x58 [] pin_get_from_name+0x6c/0x8c [] pinconf_map_to_setting+0x44/0xb0 [] pinctrl_get+0x2fc/0x430 [] devm_pinctrl_get+0x34/0x68 [] pinctrl_bind_pins+0x38/0xfc [] driver_probe_device+0x74/0x248 [] __driver_attach+0x9c/0xa0 [] bus_for_each_dev+0x70/0x94 [] driver_attach+0x24/0x28 [] bus_add_driver+0x14c/0x1dc [] driver_register+0x80/0xfc [] __platform_driver_register+0x50/0x64 [] sdhci_esdhc_imx_driver_init+0x18/0x20 [] do_one_initcall+0x38/0x168 [] kernel_init_freeable+0x104/0x1d0 [] kernel_init+0x10/0xec [] ret_from_fork+0x14/0x2c to a HARDIRQ-irq-unsafe lock: (prepare_lock){+.+.+.} ... which became HARDIRQ-irq-unsafe at: ... [] mark_lock+0x15c/0x704 [] mark_held_locks+0x70/0x150 [] trace_hardirqs_on_caller+0xb0/0x1b8 [] trace_hardirqs_on+0x14/0x18 [] mutex_trylock+0x174/0x1f0 [] clk_prepare_lock+0x14/0xf4 [] clk_notifier_register+0x34/0xf8 [] twd_clk_init+0x3c/0x50 [] do_one_initcall+0x38/0x168 [] kernel_init_freeable+0x104/0x1d0 [] kernel_init+0x10/0xec [] ret_from_fork+0x14/0x2c other info that might help us debug this: Possible interrupt unsafe locking scenario: CPU0 CPU1 ---- ---- lock(prepare_lock); local_irq_disable(); lock(&(&host->lock)->rlock); lock(prepare_lock); lock(&(&host->lock)->rlock); *** DEADLOCK *** 3 locks held by kworker/u8:1/44: #0: (kmmcd){.+.+..}, at: [] process_one_work+0x130/0x4ac #1: ((&(&host->detect)->work)){+.+...}, at: [] process_one_work+0x130/0x4ac #2: (&(&host->lock)->rlock){-.-...}, at: [] sdhci_do_set_ios+0x20/0x740 the dependencies between HARDIRQ-irq-safe lock and the holding lock: -> (&(&host->lock)->rlock){-.-...} ops: 183 { IN-HARDIRQ-W at: [] mark_lock+0x15c/0x704 [] __lock_acquire+0xb8c/0x1e14 [] lock_acquire+0xa4/0x114 [] _raw_spin_lock+0x34/0x44 [] sdhci_irq+0x20/0xa14 [] handle_irq_event_percpu+0x68/0x254 [] handle_irq_event+0x44/0x64 [] handle_fasteoi_irq+0xac/0x180 [] generic_handle_irq+0x28/0x38 [] handle_IRQ+0x40/0x98 [] gic_handle_irq+0x30/0x64 [] __irq_svc+0x44/0x58 [] pin_get_from_name+0x6c/0x8c [] pinconf_map_to_setting+0x44/0xb0 [] pinctrl_get+0x2fc/0x430 [] devm_pinctrl_get+0x34/0x68 [] pinctrl_bind_pins+0x38/0xfc [] driver_probe_device+0x74/0x248 [] __driver_attach+0x9c/0xa0 [] bus_for_each_dev+0x70/0x94 [] driver_attach+0x24/0x28 [] bus_add_driver+0x14c/0x1dc [] driver_register+0x80/0xfc [] __platform_driver_register+0x50/0x64 [] sdhci_esdhc_imx_driver_init+0x18/0x20 [] do_one_initcall+0x38/0x168 [] kernel_init_freeable+0x104/0x1d0 [] kernel_init+0x10/0xec [] ret_from_fork+0x14/0x2c IN-SOFTIRQ-W at: [] mark_lock+0x15c/0x704 [] __lock_acquire+0x5b4/0x1e14 [] lock_acquire+0xa4/0x114 [] _raw_spin_lock_irqsave+0x4c/0x60 [] sdhci_tasklet_finish+0x1c/0x120 [] tasklet_action+0x6c/0x104 [] __do_softirq+0x118/0x2d8 [] irq_exit+0xc0/0x110 [] handle_IRQ+0x44/0x98 [] gic_handle_irq+0x30/0x64 [] __irq_svc+0x44/0x58 [] pin_get_from_name+0x6c/0x8c [] pinconf_map_to_setting+0x44/0xb0 [] pinctrl_get+0x2fc/0x430 [] devm_pinctrl_get+0x34/0x68 [] pinctrl_bind_pins+0x38/0xfc [] driver_probe_device+0x74/0x248 [] __driver_attach+0x9c/0xa0 [] bus_for_each_dev+0x70/0x94 [] driver_attach+0x24/0x28 [] bus_add_driver+0x14c/0x1dc [] driver_register+0x80/0xfc [] __platform_driver_register+0x50/0x64 [] sdhci_esdhc_imx_driver_init+0x18/0x20 [] do_one_initcall+0x38/0x168 [] kernel_init_freeable+0x104/0x1d0 [] kernel_init+0x10/0xec [] ret_from_fork+0x14/0x2c INITIAL USE at: [] mark_lock+0x15c/0x704 [] __lock_acquire+0x308/0x1e14 [] lock_acquire+0xa4/0x114 [] _raw_spin_lock_irqsave+0x4c/0x60 [] sdhci_do_set_ios+0x20/0x740 [] sdhci_set_ios+0x2c/0x38 [] mmc_power_up+0x70/0xd4 [] mmc_start_host+0x44/0x70 [] mmc_add_host+0x4c/0x70 [] sdhci_add_host+0x848/0xc30 [] sdhci_esdhc_imx_probe+0x320/0x5fc [] platform_drv_probe+0x24/0x54 [] driver_probe_device+0xa4/0x248 [] __driver_attach+0x9c/0xa0 [] bus_for_each_dev+0x70/0x94 [] driver_attach+0x24/0x28 [] bus_add_driver+0x14c/0x1dc [] driver_register+0x80/0xfc [] __platform_driver_register+0x50/0x64 [] sdhci_esdhc_imx_driver_init+0x18/0x20 [] do_one_initcall+0x38/0x168 [] kernel_init_freeable+0x104/0x1d0 [] kernel_init+0x10/0xec [] ret_from_fork+0x14/0x2c } ... key at: [] __key.24505+0x0/0x8 ... acquired at: [] check_usage+0x3fc/0x618 [] check_irq_usage+0x5c/0xb8 [] __lock_acquire+0x1100/0x1e14 [] lock_acquire+0xa4/0x114 [] mutex_lock_nested+0x5c/0x39c [] clk_prepare_lock+0x80/0xf4 [] clk_get_rate+0x14/0x64 [] esdhc_pltfm_set_clock+0x20/0x2ac [] sdhci_set_clock+0x4c/0x410 [] sdhci_do_set_ios+0xe8/0x740 [] sdhci_set_ios+0x2c/0x38 [] mmc_power_off+0x64/0x84 [] mmc_rescan+0x29c/0x2dc [] process_one_work+0x1b4/0x4ac [] worker_thread+0x13c/0x410 [] kthread+0xd0/0xec [] ret_from_fork+0x14/0x2c the dependencies between the lock to be acquired and HARDIRQ-irq-unsafe lock: -> (prepare_lock){+.+.+.} ops: 314 { HARDIRQ-ON-W at: [] mark_lock+0x15c/0x704 [] mark_held_locks+0x70/0x150 [] trace_hardirqs_on_caller+0xb0/0x1b8 [] trace_hardirqs_on+0x14/0x18 [] mutex_trylock+0x174/0x1f0 [] clk_prepare_lock+0x14/0xf4 [] clk_notifier_register+0x34/0xf8 [] twd_clk_init+0x3c/0x50 [] do_one_initcall+0x38/0x168 [] kernel_init_freeable+0x104/0x1d0 [] kernel_init+0x10/0xec [] ret_from_fork+0x14/0x2c SOFTIRQ-ON-W at: [] mark_lock+0x15c/0x704 [] mark_held_locks+0x70/0x150 [] trace_hardirqs_on_caller+0xf4/0x1b8 [] trace_hardirqs_on+0x14/0x18 [] mutex_trylock+0x174/0x1f0 [] clk_prepare_lock+0x14/0xf4 [] clk_notifier_register+0x34/0xf8 [] twd_clk_init+0x3c/0x50 [] do_one_initcall+0x38/0x168 [] kernel_init_freeable+0x104/0x1d0 [] kernel_init+0x10/0xec [] ret_from_fork+0x14/0x2c RECLAIM_FS-ON-W at: [] mark_lock+0x15c/0x704 [] mark_held_locks+0x70/0x150 [] lockdep_trace_alloc+0xac/0xf8 [] __alloc_pages_nodemask+0x70/0x8dc [] new_slab+0x74/0x244 [] __slab_alloc.clone.67.clone.74+0x124/0x4dc [] kmem_cache_alloc+0x10c/0x158 [] alloc_inode+0x5c/0xa4 [] new_inode_pseudo+0x10/0x48 [] new_inode+0x18/0x30 [] debugfs_mknod.clone.16.clone.17+0x40/0x12c [] __create_file+0xc0/0x1cc [] debugfs_create_file+0x30/0x38 [] debugfs_create_x32+0x50/0x60 [] clk_debug_create_subtree+0x64/0x120 [] clk_debug_init+0xac/0x134 [] do_one_initcall+0x38/0x168 [] kernel_init_freeable+0x104/0x1d0 [] kernel_init+0x10/0xec [] ret_from_fork+0x14/0x2c INITIAL USE at: [] mark_lock+0x15c/0x704 [] __lock_acquire+0x308/0x1e14 [] lock_acquire+0xa4/0x114 [] mutex_trylock+0x108/0x1f0 [] clk_prepare_lock+0x14/0xf4 [] __clk_init+0x20/0x460 [] _clk_register+0xd0/0x164 [] clk_register+0x48/0x8c [] clk_register_fixed_rate+0x8c/0xd0 [] of_fixed_clk_setup+0x68/0x90 [] of_clk_init+0x44/0x6c [] time_init+0x2c/0x38 [] start_kernel+0x1e0/0x354 [<10008074>] 0x10008074 } ... key at: [] prepare_lock+0x38/0x48 ... acquired at: [] check_usage+0x42c/0x618 [] check_irq_usage+0x5c/0xb8 [] __lock_acquire+0x1100/0x1e14 [] lock_acquire+0xa4/0x114 [] mutex_lock_nested+0x5c/0x39c [] clk_prepare_lock+0x80/0xf4 [] clk_get_rate+0x14/0x64 [] esdhc_pltfm_set_clock+0x20/0x2ac [] sdhci_set_clock+0x4c/0x410 [] sdhci_do_set_ios+0xe8/0x740 [] sdhci_set_ios+0x2c/0x38 [] mmc_power_off+0x64/0x84 [] mmc_rescan+0x29c/0x2dc [] process_one_work+0x1b4/0x4ac [] worker_thread+0x13c/0x410 [] kthread+0xd0/0xec [] ret_from_fork+0x14/0x2c stack backtrace: CPU: 1 PID: 44 Comm: kworker/u8:1 Not tainted 3.13.0-rc7+ #401 Workqueue: kmmcd mmc_rescan Backtrace: [] (dump_backtrace) from [] (show_stack+0x18/0x1c) r6:ea3b7bb4 r5:c0a73520 r4:00000000 r3:ea352400 [] (show_stack) from [] (dump_stack+0x70/0x90) [] (dump_stack) from [] (check_usage+0x44c/0x618) r4:00000001 r3:ea352400 [] (check_usage) from [] (check_irq_usage+0x5c/0xb8) r10:00000030 r9:ea3527d0 r8:ea3527e8 r7:ea3527d0 r6:c0695968 r5:ea352400 r4:00000000 [] (check_irq_usage) from [] (__lock_acquire+0x1100/0x1e14) r8:00000002 r7:c0f1b104 r6:c0ea98fc r5:ea352400 r4:c0a5ac00 [] (__lock_acquire) from [] (lock_acquire+0xa4/0x114) r10:00000000 r9:00000002 r8:00000000 r7:00000000 r6:c09a1acc r5:ea3b6000 r4:00000000 [] (lock_acquire) from [] (mutex_lock_nested+0x5c/0x39c) r10:ea352400 r9:00000002 r8:ea3b6000 r7:00000000 r6:c0ea98fc r5:c04d10d4 r4:c09a1a94 [] (mutex_lock_nested) from [] (clk_prepare_lock+0x80/0xf4) r10:ea3b6000 r9:00000002 r8:ea397c10 r7:20000113 r6:e9841c40 r5:ea3b6000 r4:c0f25f84 [] (clk_prepare_lock) from [] (clk_get_rate+0x14/0x64) r6:e9841c40 r5:00000000 r4:ea028280 r3:c04b33f4 [] (clk_get_rate) from [] (esdhc_pltfm_set_clock+0x20/0x2ac) r5:00000000 r4:e9841c40 [] (esdhc_pltfm_set_clock) from [] (sdhci_set_clock+0x4c/0x410) r10:ea3b6000 r9:00000002 r8:00000000 r7:20000113 r6:e9841d18 r5:00000000 r4:e9841c40 r3:c04b33f4 [] (sdhci_set_clock) from [] (sdhci_do_set_ios+0xe8/0x740) r10:ea3b6000 r9:00000002 r8:00000000 r7:20000113 r6:e9841d18 r5:e9841aa8 r4:e9841c40 r3:00000000 [] (sdhci_do_set_ios) from [] (sdhci_set_ios+0x2c/0x38) r10:ea3b6000 r8:00000000 r7:ea18a100 r6:e9841aa8 r5:e9841c40 r4:e9841800 [] (sdhci_set_ios) from [] (mmc_power_off+0x64/0x84) r6:c076a858 r5:c076a858 r4:e9841800 r3:c04b0464 [] (mmc_power_off) from [] (mmc_rescan+0x29c/0x2dc) [] (mmc_rescan) from [] (process_one_work+0x1b4/0x4ac) r6:ea00dc00 r5:ea393080 r4:e9841af8 r3:c049d31c [] (process_one_work) from [] (worker_thread+0x13c/0x410) r10:ea00de80 r9:ea3b6000 r8:ea393098 r7:ea3b6000 r6:ea00dc30 r5:ea00dc00 r4:ea393080 [] (worker_thread) from [] (kthread+0xd0/0xec) r10:00000000 r9:00000000 r8:c003e7c0 r7:ea393080 r6:ea3b7f24 r5:ea392540 r4:00000000 [] (kthread) from [] (ret_from_fork+0x14/0x2c) r8:00000000 r7:00000000 r6:00000000 r5:c00450d8 r4:ea392540 static void sdhci_do_set_ios(struct sdhci_host *host, struct mmc_ios *ios) { unsigned long flags; int vdd_bit = -1; u8 ctrl; spin_lock_irqsave(&host->lock, flags); ... sdhci_set_clock(host, ios->clock); which then goes on to call esdhc_pltfm_set_clock(), and clk_get_rate(), where clk_get_rate() takes a mutex - and you can't take a mutex under an IRQs-off region. This appears to be provoked by providing the non-removable property. -- FTTC broadband for 0.8mile line: 5.8Mbps down 500kbps up. Estimation in database were 13.1 to 19Mbit for a good line, about 7.5+ for a bad. Estimate before purchase was "up to 13.2Mbit".