Re: lockdep: bdev->bd_mutex deadlock

[Peter Jones <pjones@redhat.com>]

[-- Attachment #1: Type: text/plain, Size: 1594 bytes --]

On Fri, 2006-07-07 at 09:34 +0200, Arjan van de Ven wrote:
> > <4> [<c0463f46>] __blkdev_put+0x22/0x123
> > <4> [<c0464060>] blkdev_put+0xa/0xc
> > <4> [<c04644e2>] do_open+0x313/0x385
> > <4> [<c0464759>] blkdev_open+0x1f/0x48
> 
> ok this is a missing annotation in the error path
> 
> the patch below should fix this, can you verify this?

Seems to have fixed it.  I different one this morning (I'm assuming it's
unrelated):

<4>=============================================
<4>[ INFO: possible recursive locking detected ]
<4>---------------------------------------------
<4>parted/525 is trying to acquire lock:
<4> (&bdev->bd_mutex){--..}, at: [<c05ebd9d>] mutex_lock+0x21/0x24
<4>
<4>but task is already holding lock:
<4> (&bdev->bd_mutex){--..}, at: [<c05ebd9d>] mutex_lock+0x21/0x24
<4>
<4>other info that might help us debug this:
<4>1 lock held by parted/525:
<4> #0:  (&bdev->bd_mutex){--..}, at: [<c05ebd9d>] mutex_lock+0x21/0x24
<4>
<4>stack backtrace:
<4> [<c040373c>] show_trace_log_lvl+0x54/0xfd
<4> [<c0403cba>] show_trace+0xd/0x10
<4> [<c0403d57>] dump_stack+0x19/0x1b
<4> [<c042c3ba>] __lock_acquire+0x760/0x987
<4> [<c042cb52>] lock_acquire+0x4b/0x6d
<4> [<c05ebc05>] __mutex_lock_slowpath+0xb6/0x22d
<4> [<c05ebd9d>] mutex_lock+0x21/0x24
<4> [<c04c4acf>] blkdev_ioctl+0x5dd/0x732
<4> [<c046323b>] block_ioctl+0x16/0x1b
<4> [<c046cb99>] do_ioctl+0x19/0x50
<4> [<c046cdd0>] vfs_ioctl+0x200/0x217
<4> [<c046ce2e>] sys_ioctl+0x47/0x61
<4> [<c0402dc7>] syscall_call+0x7/0xb

I'm not sure I can reproduce this one reliably :/  . Again, the whole
dmesg is attached.

-- 
  Peter

[-- Attachment #2: dmesg.txt --]
[-- Type: text/plain, Size: 16717 bytes --]

10 11 12)
<4>ACPI: PCI Interrupt Link [LNKW] (IRQs *48), disabled.
<4>ACPI: PCI Interrupt Link [LNKX] (IRQs *49), disabled.
<4>ACPI: PCI Interrupt Link [LNKY] (IRQs *50), disabled.
<4>ACPI: PCI Interrupt Link [LNKZ] (IRQs *51), disabled.
<4>ACPI: PCI Interrupt Link [LSMB] (IRQs 3 4 5 6 7 10 *11 12)
<4>ACPI: PCI Interrupt Link [LSB0] (IRQs 3 4 *5 6 7 10 11 12)
<4>ACPI: PCI Interrupt Link [LSB2] (IRQs 3 4 5 6 7 *10 11 12)
<4>ACPI: PCI Interrupt Link [LMAC] (IRQs 3 4 5 6 7 10 *11 12)
<4>ACPI: PCI Interrupt Link [LACI] (IRQs 3 4 5 6 7 10 *11 12)
<4>ACPI: PCI Interrupt Link [LMCI] (IRQs 3 4 5 6 7 10 11 12) *0, disabled.
<4>ACPI: PCI Interrupt Link [LIDE] (IRQs 3 4 5 6 7 10 11 12) *0, disabled.
<4>ACPI: PCI Interrupt Link [LSA0] (IRQs 3 4 5 6 7 10 11 12) *0, disabled.
<4>ACPI: PCI Interrupt Link [LSA1] (IRQs 3 4 5 6 7 10 11 12) *0, disabled.
<6>Linux Plug and Play Support v0.97 (c) Adam Belay
<6>pnp: PnP ACPI init
<7>PM: Adding info for No Bus:pnp0
<7>PM: Adding info for pnp:00:00
<7>PM: Adding info for pnp:00:01
<7>PM: Adding info for pnp:00:02
<7>PM: Adding info for pnp:00:03
<7>PM: Adding info for pnp:00:04
<7>PM: Adding info for pnp:00:05
<7>PM: Adding info for pnp:00:06
<7>PM: Adding info for pnp:00:07
<7>PM: Adding info for pnp:00:08
<7>PM: Adding info for pnp:00:09
<7>PM: Adding info for pnp:00:0a
<7>PM: Adding info for pnp:00:0b
<7>PM: Adding info for pnp:00:0c
<7>PM: Adding info for pnp:00:0d
<7>PM: Adding info for pnp:00:0e
<6>pnp: PnP ACPI: found 15 devices
<6>usbcore: registered new driver usbfs
<6>usbcore: registered new driver hub
<6>PCI: Using ACPI for IRQ routing
<6>PCI: If a device doesn't work, try "pci=routeirq".  If it helps, post a report
<4>PCI: BIOS reporting unknown device 80:00
<6>pnp: 00:0a: ioport range 0x4d0-0x4d1 has been reserved
<6>pnp: 00:0b: ioport range 0x400-0x47f could not be reserved
<6>pnp: 00:0b: ioport range 0x480-0x48f has been reserved
<6>pnp: 00:0b: ioport range 0xf800-0xf87f could not be reserved
<6>pnp: 00:0b: ioport range 0xf880-0xf8ff has been reserved
<6>pnp: 00:0b: ioport range 0xf900-0xf97f has been reserved
<6>pnp: 00:0b: ioport range 0xf980-0xf9ff has been reserved
<6>pnp: 00:0b: ioport range 0xfa00-0xfa7f has been reserved
<6>pnp: 00:0b: ioport range 0xfa80-0xfaff has been reserved
<6>PCI: Bridge: 0000:00:09.0
<6>  IO window: disabled.
<6>  MEM window: f2000000-f20fffff
<6>  PREFETCH window: disabled.
<3>PCI: Failed to allocate mem resource #6:20000@e0000000 for 0000:0a:00.0
<6>PCI: Bridge: 0000:00:0e.0
<6>  IO window: disabled.
<6>  MEM window: f0000000-f1ffffff
<6>  PREFETCH window: d0000000-dfffffff
<7>PCI: Setting latency timer of device 0000:00:09.0 to 64
<7>Device `[EXPA]' is not power manageable<7>PCI: Setting latency timer of device 0000:00:0e.0 to 64
<6>NET: Registered protocol family 2
<4>IP route cache hash table entries: 32768 (order: 5, 131072 bytes)
<4>TCP established hash table entries: 65536 (order: 9, 2621440 bytes)
<4>TCP bind hash table entries: 32768 (order: 8, 1441792 bytes)
<6>TCP: Hash tables configured (established 65536 bind 32768)
<6>TCP reno registered
<7>PM: Adding info for platform:pcspkr
<6>apm: BIOS not found.
<6>audit: initializing netlink socket (disabled)
<5>audit(1152267705.860:1): initialized
<4>Total HugeTLB memory allocated, 0
<5>VFS: Disk quotas dquot_6.5.1
<4>Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
<6>SELinux:  Registering netfilter hooks
<6>Initializing Cryptographic API
<6>io scheduler noop registered
<6>io scheduler anticipatory registered
<6>io scheduler deadline registered
<6>io scheduler cfq registered (default)
<7>PCI: Setting latency timer of device 0000:00:0e.0 to 64
<4>pcie_portdrv_probe->Dev[005d:10de] has invalid IRQ. Check vendor BIOS
<4>assign_interrupt_mode Found MSI capability
<7>Allocate Port Service[0000:00:0e.0:pcie00]
<7>PM: Adding info for pci_express:0000:00:0e.0:pcie00
<7>PM: Adding info for platform:vesafb.0
<3>ACPI: Getting cpuindex for acpiid 0x2
<3>ACPI: Getting cpuindex for acpiid 0x3
<3>ACPI: Getting cpuindex for acpiid 0x4
<7>PM: Adding info for No Bus:pnp1
<6>isapnp: Scanning for PnP cards...
<6>isapnp: No Plug & Play device found
<6>Real Time Clock Driver v1.12ac
<6>Non-volatile memory driver v1.2
<6>Linux agpgart interface v0.101 (c) Dave Jones
<6>Serial: 8250/16550 driver $Revision: 1.90 $ 4 ports, IRQ sharing enabled
<7>PM: Adding info for platform:serial8250
<6>serial8250: ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
<6>00:07: ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
<7>PM: Adding info for No Bus:isa
<4>RAMDISK driver initialized: 16 RAM disks of 16384K size 1024 blocksize
<6>Uniform Multi-Platform E-IDE driver Revision: 7.00alpha2
<6>ide: Assuming 33MHz system bus speed for PIO modes; override with idebus=xx
<6>NFORCE-CK804: IDE controller at PCI slot 0000:00:06.0
<7>Device `[IDE]' is not power manageable<6>NFORCE-CK804: chipset revision 242
<6>NFORCE-CK804: not 100% native mode: will probe irqs later
<6>NFORCE-CK804: 0000:00:06.0 (rev f2) UDMA133 controller
<6>    ide0: BM-DMA at 0x28a0-0x28a7, BIOS settings: hda:DMA, hdb:pio
<6>    ide1: BM-DMA at 0x28a8-0x28af, BIOS settings: hdc:pio, hdd:pio
<7>Probing IDE interface ide0...
<4>hda: PCRW804, ATAPI CD/DVD-ROM drive
<7>PM: Adding info for No Bus:ide0
<4>ide0 at 0x1f0-0x1f7,0x3f6 on irq 14
<7>PM: Adding info for ide:0.0
<7>Probing IDE interface ide1...
<7>Probing IDE interface ide1...
<4>ide-floppy driver 0.99.newide
<6>usbcore: registered new driver libusual
<6>usbcore: registered new driver hiddev
<6>usbcore: registered new driver usbhid
<6>drivers/usb/input/hid-core.c: v2.6:USB HID core driver
<6>PNP: PS/2 Controller [PNP0303:KBD,PNP0f0e:PS2M] at 0x60,0x64 irq 1,12
<7>PM: Adding info for platform:i8042
<6>serio: i8042 AUX port at 0x60,0x64 irq 12
<6>serio: i8042 KBD port at 0x60,0x64 irq 1
<7>PM: Adding info for serio:serio0
<6>mice: PS/2 mouse device common for all mice
<6>md: md driver 0.90.3 MAX_MD_DEVS=256, MD_SB_DISKS=27
<6>md: bitmap version 4.39
<6>TCP bic registered
<6>Initializing IPsec netlink socket
<6>NET: Registered protocol family 1
<6>NET: Registered protocol family 17
<4>Using IPI Shortcut mode
<7>PM: Adding info for serio:serio1
<6>ACPI: (supports S0 S1 S3 S4 S5)
<6>Freeing unused kernel memory: 196k freed
<6>Time: tsc clocksource has been installed.
<4>Write protecting the kernel read-only data: 358k
<6>input: AT Translated Set 2 keyboard as /class/input/input0
<6>loop: loaded (max 8 devices)
<6>input: PS/2 Generic Mouse as /class/input/input1
<4>floppy0: no floppy controllers found
<6>BIOS EDD facility v0.16 2004-Jun-25, 1 devices found
<6>input: PC Speaker as /class/input/input2
<6>squashfs: version 3.0 (2006/03/15) Phillip Lougher
<6>hda: ATAPI 32X CD-ROM CD-R/RW drive, 2048kB Cache, DMA
<6>Uniform CD-ROM driver Revision: 3.20
<5>SCSI subsystem initialized
<7>Device `[USB2]' is not power manageableACPI: PCI Interrupt Link [LSB2] enabled at IRQ 10
<7>PCI: setting IRQ 10 as level-triggered
<6>ACPI: PCI Interrupt 0000:00:02.1[B] -> Link [LSB2] -> GSI 10 (level, low) -> IRQ 10
<7>PCI: Setting latency timer of device 0000:00:02.1 to 64
<6>ehci_hcd 0000:00:02.1: EHCI Host Controller
<6>ehci_hcd 0000:00:02.1: new USB bus registered, assigned bus number 1
<6>ehci_hcd 0000:00:02.1: debug port 1
<7>PCI: cache line size of 64 is not supported by device 0000:00:02.1
<6>ehci_hcd 0000:00:02.1: irq 10, io mem 0xfebf0000
<6>ehci_hcd 0000:00:02.1: USB 2.0 started, EHCI 1.00, driver 10 Dec 2004
<7>PM: Adding info for usb:usb1
<7>PM: Adding info for No Bus:usbdev1.1_ep00
<6>usb usb1: configuration #1 chosen from 1 choice
<7>PM: Adding info for usb:1-0:1.0
<6>hub 1-0:1.0: USB hub found
<6>hub 1-0:1.0: 10 ports detected
<7>PM: Adding info for No Bus:usbdev1.1_ep81
<7>PM: Adding info for No Bus:usbdev1.1
<7>ohci_hcd: 2005 April 22 USB 1.1 'Open' Host Controller (OHCI) Driver (PCI)
<7>Device `[USB0]' is not power manageableACPI: PCI Interrupt Link [LSB0] enabled at IRQ 5
<7>PCI: setting IRQ 5 as level-triggered
<6>ACPI: PCI Interrupt 0000:00:02.0[A] -> Link [LSB0] -> GSI 5 (level, low) -> IRQ 5
<7>PCI: Setting latency timer of device 0000:00:02.0 to 64
<6>ohci_hcd 0000:00:02.0: OHCI Host Controller
<6>ohci_hcd 0000:00:02.0: new USB bus registered, assigned bus number 2
<6>ohci_hcd 0000:00:02.0: irq 5, io mem 0xf2100000
<7>PM: Adding info for usb:usb2
<7>PM: Adding info for No Bus:usbdev2.1_ep00
<6>usb usb2: configuration #1 chosen from 1 choice
<7>PM: Adding info for usb:2-0:1.0
<6>hub 2-0:1.0: USB hub found
<6>hub 2-0:1.0: 10 ports detected
<6>usb 1-4: new high speed USB device using ehci_hcd and address 2
<7>PM: Adding info for No Bus:usbdev2.1_ep81
<7>PM: Adding info for No Bus:usbdev2.1
<7>PM: Adding info for usb:1-4
<7>PM: Adding info for No Bus:usbdev1.2_ep00
<6>usb 1-4: configuration #1 chosen from 1 choice
<7>PM: Adding info for usb:1-4:1.0
<7>PM: Adding info for No Bus:usbdev1.2_ep81
<7>PM: Adding info for No Bus:usbdev1.2_ep02
<7>PM: Adding info for usb:1-4:1.1
<7>PM: Adding info for No Bus:hiddev0
<6>hiddev96: USB HID v1.10 Device [DMI      WD1600BB-00GUA0 ] on usb-0000:00:02.1-4
<7>PM: Adding info for No Bus:usbdev1.2_ep83
<7>PM: Adding info for No Bus:usbdev1.2
<6>Initializing USB Mass Storage driver...
<6>scsi0 : SCSI emulation for USB Mass Storage devices
<7>PM: Adding info for No Bus:host0
<7>usb-storage: device found at 2
<7>usb-storage: waiting for device to settle before scanning
<6>usbcore: registered new driver usb-storage
<6>USB Mass Storage support registered.
<7>ieee1394: Initialized config rom entry `ip1394'
<4>ACPI: PCI Interrupt Link [LNKD] enabled at IRQ 10
<6>ACPI: PCI Interrupt 0000:05:05.0[A] -> Link [LNKD] -> GSI 10 (level, low) -> IRQ 10
<7>PM: Adding info for ieee1394:fw-host0
<6>ohci1394: fw-host0: OHCI-1394 1.1 (PCI): IRQ=[10]  MMIO=[f2004000-f20047ff]  Max Packet=[2048]  IR/IT contexts=[4/8]
<7>PM: Adding info for No Bus:target0:0:0
<5>  Vendor: DMI       Model: WD1600BB-00GUA0   Rev: 3.53
<5>  Type:   Direct-Access                      ANSI SCSI revision: 00
<7>PM: Adding info for scsi:0:0:0:0
<5>SCSI device sda: 312581808 512-byte hdwr sectors (160042 MB)
<5>sda: Write Protect is off
<7>sda: Mode Sense: 86 0b 00 02
<3>sda: assuming drive cache: write through
<5>SCSI device sda: 312581808 512-byte hdwr sectors (160042 MB)
<5>sda: Write Protect is off
<7>sda: Mode Sense: 86 0b 00 02
<3>sda: assuming drive cache: write through
<6> sda: sda1 sda4
<5>sd 0:0:0:0: Attached scsi disk sda
<7>PM: Adding info for No Bus:target0:0:1
<7>PM: Removing info for No Bus:target0:0:1
<7>PM: Adding info for No Bus:target0:0:2
<7>PM: Removing info for No Bus:target0:0:2
<7>PM: Adding info for No Bus:target0:0:3
<7>PM: Removing info for No Bus:target0:0:3
<7>PM: Adding info for No Bus:target0:0:4
<7>PM: Removing info for No Bus:target0:0:4
<7>PM: Adding info for No Bus:target0:0:5
<7>PM: Removing info for No Bus:target0:0:5
<7>PM: Adding info for No Bus:target0:0:6
<7>PM: Removing info for No Bus:target0:0:6
<7>PM: Adding info for No Bus:target0:0:7
<7>PM: Removing info for No Bus:target0:0:7
<7>usb-storage: device scan complete
<7>PM: Adding info for ieee1394:0060b00000183041
<7>ieee1394: Host added: ID:BUS[0-00:1023]  GUID[0060b00000183041]
<7>PM: Adding info for ieee1394:0060b00000183041-0
<6>forcedeth.c: Reverse Engineered nForce ethernet driver. Version 0.56.
<7>Device `[MAC0]' is not power manageableACPI: PCI Interrupt Link [LMAC] enabled at IRQ 11
<7>PCI: setting IRQ 11 as level-triggered
<6>ACPI: PCI Interrupt 0000:00:0a.0[A] -> Link [LMAC] -> GSI 11 (level, low) -> IRQ 11
<7>PCI: Setting latency timer of device 0000:00:0a.0 to 64
<6>forcedeth: using HIGHDMA
<6>eth0: forcedeth.c: subsystem: 0103c:1500 bound to 0000:00:0a.0
<7>libata version 2.00 loaded.
<4>eth0: no link during initialization.
<6>eth0: link up.
<4>Unable to identify CD-ROM format.
<4>VFS: Can't find an ext2 filesystem on dev loop0.
<6>security:  3 users, 6 roles, 1398 types, 148 bools, 1 sens, 256 cats
<6>security:  58 classes, 40314 rules
<6>SELinux:  Completing initialization.
<6>SELinux:  Setting up existing superblocks.
<6>SELinux: initialized (dev loop0, type squashfs), not configured for labeling
<6>SELinux: initialized (dev 0:13, type nfs), uses genfs_contexts
<6>SELinux: initialized (dev rpc_pipefs, type rpc_pipefs), uses genfs_contexts
<6>SELinux: initialized (dev usbfs, type usbfs), uses genfs_contexts
<6>SELinux: initialized (dev ramfs, type ramfs), uses genfs_contexts
<6>SELinux: initialized (dev ramfs, type ramfs), uses genfs_contexts
<6>SELinux: initialized (dev tmpfs, type tmpfs), uses transition SIDs
<6>SELinux: initialized (dev debugfs, type debugfs), uses genfs_contexts
<6>SELinux: initialized (dev selinuxfs, type selinuxfs), uses genfs_contexts
<6>SELinux: initialized (dev mqueue, type mqueue), uses transition SIDs
<6>SELinux: initialized (dev hugetlbfs, type hugetlbfs), uses genfs_contexts
<6>SELinux: initialized (dev devpts, type devpts), uses transition SIDs
<6>SELinux: initialized (dev eventpollfs, type eventpollfs), uses genfs_contexts
<6>SELinux: initialized (dev inotifyfs, type inotifyfs), uses genfs_contexts
<6>SELinux: initialized (dev tmpfs, type tmpfs), uses transition SIDs
<6>SELinux: initialized (dev futexfs, type futexfs), uses genfs_contexts
<6>SELinux: initialized (dev pipefs, type pipefs), uses task SIDs
<6>SELinux: initialized (dev sockfs, type sockfs), uses task SIDs
<6>SELinux: initialized (dev proc, type proc), uses genfs_contexts
<6>SELinux: initialized (dev bdev, type bdev), uses genfs_contexts
<6>SELinux: initialized (dev rootfs, type rootfs), uses genfs_contexts
<6>SELinux: initialized (dev sysfs, type sysfs), uses genfs_contexts
<5>audit(1152267732.289:2): policy loaded auid=4294967295
<5>audit(1152267732.289:3): avc:  granted  { load_policy } for  pid=428 comm="load_policy" scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:object_r:security_t:s0 tclass=security
<5>audit(1152267732.305:4): avc:  denied  { transition } for  pid=429 comm="loader" name="bash" dev=loop0 ino=6228 scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:system_r:anaconda_t:s0 tclass=process
<6>md: raid0 personality registered for level 0
<6>md: raid1 personality registered for level 1
<6>JFS: nTxBlock = 7062, nTxLock = 56501
<6>SGI XFS with ACLs, security attributes, large block numbers, no debug enabled
<6>SGI XFS Quota Management subsystem
<6>device-mapper: ioctl: 4.7.0-ioctl (2006-06-24) initialised: dm-devel@redhat.com
<4>EXT2-fs warning (device dm-0): ext2_fill_super: mounting ext3 filesystem as ext2
<6>SELinux: initialized (dev dm-0, type ext2), uses xattr
<5>SCSI device sda: 312581808 512-byte hdwr sectors (160042 MB)
<5>sda: Write Protect is off
<7>sda: Mode Sense: 86 0b 00 02
<3>sda: assuming drive cache: write through
<6> sda: sda2 sda4
<5>SCSI device sda: 312581808 512-byte hdwr sectors (160042 MB)
<5>sda: Write Protect is off
<7>sda: Mode Sense: 86 0b 00 02
<3>sda: assuming drive cache: write through
<6> sda: sda2 sda4
<5>SCSI device sda: 312581808 512-byte hdwr sectors (160042 MB)
<5>sda: Write Protect is off
<7>sda: Mode Sense: 86 0b 00 02
<3>sda: assuming drive cache: write through
<6> sda: sda3 < sda5 > sda4
<5>SCSI device sda: 312581808 512-byte hdwr sectors (160042 MB)
<5>sda: Write Protect is off
<7>sda: Mode Sense: 86 0b 00 02
<3>sda: assuming drive cache: write through
<6> sda: sda3 < sda5 > sda4
<4>
<4>=============================================
<4>[ INFO: possible recursive locking detected ]
<4>---------------------------------------------
<4>parted/525 is trying to acquire lock:
<4> (&bdev->bd_mutex){--..}, at: [<c05ebd9d>] mutex_lock+0x21/0x24
<4>
<4>but task is already holding lock:
<4> (&bdev->bd_mutex){--..}, at: [<c05ebd9d>] mutex_lock+0x21/0x24
<4>
<4>other info that might help us debug this:
<4>1 lock held by parted/525:
<4> #0:  (&bdev->bd_mutex){--..}, at: [<c05ebd9d>] mutex_lock+0x21/0x24
<4>
<4>stack backtrace:
<4> [<c040373c>] show_trace_log_lvl+0x54/0xfd
<4> [<c0403cba>] show_trace+0xd/0x10
<4> [<c0403d57>] dump_stack+0x19/0x1b
<4> [<c042c3ba>] __lock_acquire+0x760/0x987
<4> [<c042cb52>] lock_acquire+0x4b/0x6d
<4> [<c05ebc05>] __mutex_lock_slowpath+0xb6/0x22d
<4> [<c05ebd9d>] mutex_lock+0x21/0x24
<4> [<c04c4acf>] blkdev_ioctl+0x5dd/0x732
<4> [<c046323b>] block_ioctl+0x16/0x1b
<4> [<c046cb99>] do_ioctl+0x19/0x50
<4> [<c046cdd0>] vfs_ioctl+0x200/0x217
<4> [<c046ce2e>] sys_ioctl+0x47/0x61
<4> [<c0402dc7>] syscall_call+0x7/0xb