From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by smtp.lore.kernel.org (Postfix) with ESMTP id 58B74EE49A6 for ; Sun, 20 Aug 2023 11:13:06 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S229853AbjHTLNF (ORCPT ); Sun, 20 Aug 2023 07:13:05 -0400 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:52408 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S230429AbjHTLND (ORCPT ); Sun, 20 Aug 2023 07:13:03 -0400 Received: from mout-p-201.mailbox.org (mout-p-201.mailbox.org [IPv6:2001:67c:2050:0:465::201]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id EFB461735 for ; Sun, 20 Aug 2023 04:09:53 -0700 (PDT) Received: from smtp102.mailbox.org (smtp102.mailbox.org [10.196.197.102]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange ECDHE (P-384) server-signature RSA-PSS (4096 bits) server-digest SHA256) (No client certificate requested) by mout-p-201.mailbox.org (Postfix) with ESMTPS id 4RTCYl4bRHz9sJ6; Sun, 20 Aug 2023 13:09:47 +0200 (CEST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=mailbox.org; s=mail20150812; t=1692529787; h=from:from:reply-to:subject:subject:date:date:message-id:message-id: to:to:cc:cc:mime-version:mime-version:content-type:content-type; bh=GuxPY5HeDyGVS6d1I+g9KoBC8b9UKTCWhZgshsaveDw=; b=M4eOQdKFC95iF8N09icN1P+2PQFoPikJ/QLT2xCl8rPLidATQpp5+SG3NbyzGbWZVYQPov gy1yznSoV0oFNj8HLmJMdgX7hcZB7fY6UjxfRRg44AcWN4rRV2F2RZUkUo+qNpgUe3IJ4j 31DQHkSqXp7+UBG2fO1WJuFCZA7noSaQi/dcLYgw8NcZ07ndFEyy9LEDZFfDNhx9sJUUt6 O0l+uCYPvxwK1oYr7TCfierTl3kOyBBOIWh84QVP02z3NRYaDeB55cXuvs3DjVslmKfY82 P/Mt4B2p9PUTxBdaSssZGVtgtEmaPmnZLh8t8dTiONMHm216K1FDhf4BlwRuhA== Date: Sun, 20 Aug 2023 13:09:42 +0200 From: Erhard Furtner To: linux1394-devel@lists.sourceforge.net Cc: linux-kernel@vger.kernel.org Subject: WARNING: possible irq lock inversion dependency detected, at: close_transaction+0x48/0x230 [firewire_core] but this lock took another, SOFTIRQ-unsafe lock in the past: (fs_reclaim){+.+.}-{0:0} (kernel 6.5-rc6) Message-ID: <20230820130942.619cb7de@yea> MIME-Version: 1.0 Content-Type: multipart/mixed; boundary="MP_/eAr5NfwxmJBLjRXMjKERx3h" X-MBO-RS-META: g3kdjbghpouc31q748ie49xsyn1rw8mc X-MBO-RS-ID: e2cadf7ea2d04d6c1e7 Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org --MP_/eAr5NfwxmJBLjRXMjKERx3h Content-Type: text/plain; charset=US-ASCII Content-Transfer-Encoding: 7bit Content-Disposition: inline Getting this at every boot on my PowerMac G5 11,2 (kernel 6.5-rc6) when CONFIG_PROVE_LOCKING=y is set: [...] ======================================================== WARNING: possible irq lock inversion dependency detected 6.5.0-rc6-PMacG5-dirty #2 Tainted: G T -------------------------------------------------------- kworker/1:1/60 just changed the state of lock: c000000022802108 (&card->lock){..-.}-{2:2}, at: close_transaction+0x48/0x230 [firewire_core] but this lock took another, SOFTIRQ-unsafe lock in the past: (fs_reclaim){+.+.}-{0:0} and interrupts could create inverse lock ordering between them. other info that might help us debug this: Possible interrupt unsafe locking scenario: CPU0 CPU1 ---- ---- lock(fs_reclaim); local_irq_disable(); lock(&card->lock); lock(fs_reclaim); lock(&card->lock); *** DEADLOCK *** 2 locks held by kworker/1:1/60: #0: c000000020316538 ((wq_completion)firewire){+.+.}-{0:0}, at: process_one_work+0x26c/0x720 #1: c0000000037dbea8 ((work_completion)(&(&device->work)->work)){+.+.}-{0:0}, at: process_one_work+0x26c/0x720 the shortest dependencies between 2nd lock and 1st lock: -> (fs_reclaim){+.+.}-{0:0} { HARDIRQ-ON-W at: lock_acquire+0x124/0x3e0 fs_reclaim_acquire+0x104/0x140 __kmem_cache_alloc_node+0x7c/0x570 kmalloc_trace+0x50/0x1a0 pmf_register_driver+0x120/0x530 pmac_pfunc_base_install+0x210/0x684 smp_core99_probe+0x1a4/0x944 smp_prepare_cpus+0x5b0/0x664 kernel_init_freeable+0x398/0x6d8 kernel_init+0x28/0x1a0 ret_from_kernel_user_thread+0x14/0x1c SOFTIRQ-ON-W at: lock_acquire+0x124/0x3e0 fs_reclaim_acquire+0x104/0x140 __kmem_cache_alloc_node+0x7c/0x570 kmalloc_trace+0x50/0x1a0 pmf_register_driver+0x120/0x530 pmac_pfunc_base_install+0x210/0x684 smp_core99_probe+0x1a4/0x944 smp_prepare_cpus+0x5b0/0x664 kernel_init_freeable+0x398/0x6d8 kernel_init+0x28/0x1a0 ret_from_kernel_user_thread+0x14/0x1c INITIAL USE at: lock_acquire+0x124/0x3e0 fs_reclaim_acquire+0x104/0x140 __kmem_cache_alloc_node+0x7c/0x570 kmalloc_trace+0x50/0x1a0 pmf_register_driver+0x120/0x530 pmac_pfunc_base_install+0x210/0x684 smp_core99_probe+0x1a4/0x944 smp_prepare_cpus+0x5b0/0x664 kernel_init_freeable+0x398/0x6d8 kernel_init+0x28/0x1a0 ret_from_kernel_user_thread+0x14/0x1c } ... key at: [] __fs_reclaim_map+0x0/0x28 ... acquired at: lock_acquire+0x124/0x3e0 fs_reclaim_acquire+0x104/0x140 __kmem_cache_alloc_node+0x7c/0x570 __kmalloc+0x64/0x320 fw_core_handle_bus_reset+0x740/0xcb0 [firewire_core] bus_reset_work+0x350/0x9f0 [firewire_ohci] process_one_work+0x320/0x720 worker_thread+0x98/0x500 kthread+0x148/0x150 start_kernel_thread+0x14/0x18 -> (&card->lock){..-.}-{2:2} { IN-SOFTIRQ-W at: lock_acquire+0x124/0x3e0 _raw_spin_lock_irqsave+0x64/0xd0 close_transaction+0x48/0x230 [firewire_core] handle_at_packet+0x158/0x260 [firewire_ohci] context_tasklet+0x194/0x200 [firewire_ohci] tasklet_action_common.constprop.0+0x2ac/0x5e0 __do_softirq+0x180/0x5bc do_softirq_own_stack+0x38/0x80 __irq_exit_rcu+0x168/0x1c0 irq_exit+0x18/0x60 arch_local_irq_restore+0x13c/0x3a0 _raw_spin_unlock_irq+0x48/0x90 wq_worker_sleeping+0xfc/0x130 schedule+0xf0/0x190 schedule_timeout+0x234/0x2b0 __wait_for_common+0x100/0x2d0 fw_run_transaction+0x16c/0x1e0 [firewire_core] read_rom+0x8c/0x110 [firewire_core] read_config_rom+0xa4/0x560 [firewire_core] fw_device_init+0x38/0x430 [firewire_core] fw_device_workfn+0x24/0x50 [firewire_core] process_one_work+0x320/0x720 worker_thread+0x98/0x500 kthread+0x148/0x150 start_kernel_thread+0x14/0x18 INITIAL USE at: lock_acquire+0x124/0x3e0 _raw_spin_lock_irqsave+0x64/0xd0 fw_core_handle_bus_reset+0x7c/0xcb0 [firewire_core] bus_reset_work+0x350/0x9f0 [firewire_ohci] process_one_work+0x320/0x720 worker_thread+0x98/0x500 kthread+0x148/0x150 start_kernel_thread+0x14/0x18 } ... key at: [] __key.5+0x0/0x10 [firewire_core] ... acquired at: __lock_acquire+0xa54/0x1f70 lock_acquire+0x124/0x3e0 _raw_spin_lock_irqsave+0x64/0xd0 close_transaction+0x48/0x230 [firewire_core] handle_at_packet+0x158/0x260 [firewire_ohci] context_tasklet+0x194/0x200 [firewire_ohci] tasklet_action_common.constprop.0+0x2ac/0x5e0 __do_softirq+0x180/0x5bc do_softirq_own_stack+0x38/0x80 __irq_exit_rcu+0x168/0x1c0 irq_exit+0x18/0x60 arch_local_irq_restore+0x13c/0x3a0 _raw_spin_unlock_irq+0x48/0x90 wq_worker_sleeping+0xfc/0x130 schedule+0xf0/0x190 schedule_timeout+0x234/0x2b0 __wait_for_common+0x100/0x2d0 fw_run_transaction+0x16c/0x1e0 [firewire_core] read_rom+0x8c/0x110 [firewire_core] read_config_rom+0xa4/0x560 [firewire_core] fw_device_init+0x38/0x430 [firewire_core] fw_device_workfn+0x24/0x50 [firewire_core] process_one_work+0x320/0x720 worker_thread+0x98/0x500 kthread+0x148/0x150 start_kernel_thread+0x14/0x18 stack backtrace: CPU: 1 PID: 60 Comm: kworker/1:1 Tainted: G T 6.5.0-rc6-PMacG5-dirty #2 Hardware name: PowerMac11,2 PPC970MP 0x440101 PowerMac Workqueue: firewire fw_device_workfn [firewire_core] Call Trace: [c00000000fff38a0] [c000000000ff342c] dump_stack_lvl+0xb0/0x11c (unreliable) [c00000000fff38e0] [c00000000018f65c] print_irq_inversion_bug.part.0+0x220/0x27c [c00000000fff3970] [c000000000188288] mark_lock+0xbe8/0x1620 [c00000000fff3ab0] [c000000000189af4] __lock_acquire+0xa54/0x1f70 [c00000000fff3be0] [c00000000018bdc4] lock_acquire+0x124/0x3e0 [c00000000fff3ce0] [c000000001042024] _raw_spin_lock_irqsave+0x64/0xd0 [c00000000fff3d20] [c0003d00004076e0] close_transaction+0x48/0x230 [firewire_core] [c00000000fff3d90] [c0003d00004f99b0] handle_at_packet+0x158/0x260 [firewire_ohci] [c00000000fff3de0] [c0003d00004fcf9c] context_tasklet+0x194/0x200 [firewire_ohci] [c00000000fff3e40] [c0000000000e363c] tasklet_action_common.constprop.0+0x2ac/0x5e0 [c00000000fff3ec0] [c000000001043750] __do_softirq+0x180/0x5bc [c00000000fff3fe0] [c000000000014008] do_softirq_own_stack+0x38/0x80 [c0000000037db6d0] [c0000000000e21e8] __irq_exit_rcu+0x168/0x1c0 [c0000000037db700] [c0000000000e3048] irq_exit+0x18/0x60 [c0000000037db720] [c0000000000304ec] arch_local_irq_restore+0x13c/0x3a0 [c0000000037db7b0] [c0000000010424c8] _raw_spin_unlock_irq+0x48/0x90 [c0000000037db7e0] [c000000000113e0c] wq_worker_sleeping+0xfc/0x130 [c0000000037db810] [c000000001035110] schedule+0xf0/0x190 [c0000000037db880] [c0000000010413a4] schedule_timeout+0x234/0x2b0 [c0000000037db960] [c000000001035e90] __wait_for_common+0x100/0x2d0 [c0000000037db9f0] [c0003d0000406dd4] fw_run_transaction+0x16c/0x1e0 [firewire_core] [c0000000037dbc40] [c0003d0000401fe4] read_rom+0x8c/0x110 [firewire_core] [c0000000037dbc90] [c0003d00004030dc] read_config_rom+0xa4/0x560 [firewire_core] [c0000000037dbd70] [c0003d0000403900] fw_device_init+0x38/0x430 [firewire_core] [c0000000037dbe20] [c0003d000040195c] fw_device_workfn+0x24/0x50 [firewire_core] [c0000000037dbe40] [c0000000001100b0] process_one_work+0x320/0x720 [c0000000037dbf10] [c000000000110548] worker_thread+0x98/0x500 [c0000000037dbf90] [c00000000011f938] kthread+0x148/0x150 [c0000000037dbfe0] [c00000000000bfb0] start_kernel_thread+0x14/0x18 firewire_core 0001:03:0e.0: created device fw0: GUID 001451fffe26fa7e, S800 firewire_core 0001:03:0e.0: phy config: new root=ffc1, gap_count=5 [...] Some data on the machine: # lspci 0000:00:0b.0 PCI bridge: Apple Inc. CPC945 PCIe Bridge 0000:0a:00.0 VGA compatible controller: NVIDIA Corporation NV43 [GeForce 6600 LE] (rev a2) 0001:00:00.0 Host bridge: Apple Inc. U4 HT Bridge 0001:00:01.0 PCI bridge: Broadcom BCM5780 [HT2000] PCI-X bridge (rev a3) 0001:00:02.0 PCI bridge: Broadcom BCM5780 [HT2000] PCI-X bridge (rev a3) 0001:00:03.0 PCI bridge: Broadcom BCM5780 [HT2000] PCI-Express Bridge (rev a3) 0001:00:04.0 PCI bridge: Broadcom BCM5780 [HT2000] PCI-Express Bridge (rev a3) 0001:00:05.0 PCI bridge: Broadcom BCM5780 [HT2000] PCI-Express Bridge (rev a3) 0001:00:06.0 PCI bridge: Broadcom BCM5780 [HT2000] PCI-Express Bridge (rev a3) 0001:00:07.0 PCI bridge: Apple Inc. Shasta PCI Bridge 0001:00:08.0 PCI bridge: Apple Inc. Shasta PCI Bridge 0001:00:09.0 PCI bridge: Apple Inc. Shasta PCI Bridge 0001:01:07.0 Unassigned class [ff00]: Apple Inc. Shasta Mac I/O 0001:01:0b.0 USB controller: NEC Corporation OHCI USB Controller (rev 43) 0001:01:0b.1 USB controller: NEC Corporation OHCI USB Controller (rev 43) 0001:01:0b.2 USB controller: NEC Corporation uPD72010x USB 2.0 Controller (rev 04) 0001:03:0c.0 IDE interface: Broadcom K2 SATA 0001:03:0d.0 Unassigned class [ff00]: Apple Inc. Shasta IDE 0001:03:0e.0 FireWire (IEEE 1394): Apple Inc. Shasta Firewire 0001:05:04.0 Ethernet controller: Broadcom Inc. and subsidiaries NetXtreme BCM5780 Gigabit Ethernet (rev 03) 0001:05:04.1 Ethernet controller: Broadcom Inc. and subsidiaries NetXtreme BCM5780 Gigabit Ethernet (rev 03) 0001:06:00.0 VGA compatible controller: Advanced Micro Devices, Inc. [AMD/ATI] RV516 [Radeon X1300/X1550 Series] 0001:06:00.1 Display controller: Advanced Micro Devices, Inc. [AMD/ATI] RV516 [Radeon X1300/X1550 Series] (Secondary) 0001:08:00.0 Ethernet controller: Realtek Semiconductor Co., Ltd. RTL8111/8168/8411 PCI Express Gigabit Ethernet Controller (rev 06) 0001:09:00.0 Non-Volatile memory controller: Sandisk Corp WD Black SN750 / PC SN730 NVMe SSD # lspci -vv -s 0001:03:0e.0 0001:03:0e.0 FireWire (IEEE 1394): Apple Inc. Shasta Firewire (prog-if 10 [OHCI]) Subsystem: Apple Inc. Shasta Firewire Device tree node: /sys/firmware/devicetree/base/ht@0,f2000000/pci@9/firewire@e Control: I/O- Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B- DisINTx- Status: Cap+ 66MHz- UDF- FastB2B+ ParErr- DEVSEL=medium >TAbort- SERR-