2.6.17-rc5-mm3: bad unlock ordering (reiser4?)

2.6.17-rc5-mm3: bad unlock ordering (reiser4?)

[Barry K. Nathan]

This is 2.6.17-rc5-mm3 + the 3 ns83820 patches. I have no idea what I
did to cause this to happen (i.e. it claims that mv is the culprit,
but I don't think I was running mv myself -- I guess it was spawned by
another process, but I have *no* idea what would have done it). I'm
including the full dmesg.
-- 
-Barry K. Nathan <barryn@pobox.com>

[    0.000000] Linux version 2.6.17-rc5-mm3 (barryn@nserv) (gcc
version 4.1.1) #1 Sun Jun 4 02:03:43 PDT 2006
[    0.000000] BIOS-provided physical RAM map:
[    0.000000] sanitize start
[    0.000000] sanitize end
[    0.000000] copy_e820_map() start: 0000000000000000 size:
000000000009fc00 end: 000000000009fc00 type: 1
[    0.000000] copy_e820_map() type is E820_RAM
[    0.000000] add_memory_region(0000000000000000, 000000000009fc00, 1)
[    0.000000] copy_e820_map() start: 000000000009fc00 size:
0000000000000400 end: 00000000000a0000 type: 2
[    0.000000] add_memory_region(000000000009fc00, 0000000000000400, 2)
[    0.000000] copy_e820_map() start: 00000000000f0000 size:
0000000000010000 end: 0000000000100000 type: 2
[    0.000000] add_memory_region(00000000000f0000, 0000000000010000, 2)
[    0.000000] copy_e820_map() start: 0000000000100000 size:
000000001fef0000 end: 000000001fff0000 type: 1
[    0.000000] copy_e820_map() type is E820_RAM
[    0.000000] add_memory_region(0000000000100000, 000000001fef0000, 1)
[    0.000000] copy_e820_map() start: 000000001fff0000 size:
0000000000008000 end: 000000001fff8000 type: 3
[    0.000000] add_memory_region(000000001fff0000, 0000000000008000, 3)
[    0.000000] copy_e820_map() start: 000000001fff8000 size:
0000000000008000 end: 0000000020000000 type: 4
[    0.000000] add_memory_region(000000001fff8000, 0000000000008000, 4)
[    0.000000] copy_e820_map() start: 00000000ffff0000 size:
0000000000010000 end: 0000000100000000 type: 2
[    0.000000] add_memory_region(00000000ffff0000, 0000000000010000, 2)
[    0.000000]  BIOS-e820: 0000000000000000 - 000000000009fc00 (usable)
[    0.000000]  BIOS-e820: 000000000009fc00 - 00000000000a0000 (reserved)
[    0.000000]  BIOS-e820: 00000000000f0000 - 0000000000100000 (reserved)
[    0.000000]  BIOS-e820: 0000000000100000 - 000000001fff0000 (usable)
[    0.000000]  BIOS-e820: 000000001fff0000 - 000000001fff8000 (ACPI data)
[    0.000000]  BIOS-e820: 000000001fff8000 - 0000000020000000 (ACPI NVS)
[    0.000000]  BIOS-e820: 00000000ffff0000 - 0000000100000000 (reserved)
[    0.000000] 511MB LOWMEM available.
[    0.000000] On node 0 totalpages: 131056
[    0.000000]   DMA zone: 4096 pages, LIFO batch:0
[    0.000000]   Normal zone: 126960 pages, LIFO batch:31
[    0.000000] DMI 2.3 present.
[    0.000000] ACPI: RSDP (v000 AMI
) @ 0x000fa8f0
[    0.000000] ACPI: RSDT (v001 AMIINT          0x00000010 MSFT
0x00000097) @ 0x1fff0000
[    0.000000] ACPI: FADT (v001 AMIINT          0x00000010 MSFT
0x00000097) @ 0x1fff0030
[    0.000000] ACPI: DSDT (v001 AMD75X IRONGATE 0x00001000 MSFT
0x0100000b) @ 0x00000000
[    0.000000] Allocating PCI resources starting at 30000000 (gap:
20000000:dfff0000)
[    0.000000] Detected 805.700 MHz processor.
[   73.423215] Built 1 zonelists
[   73.423223] Kernel command line: BOOT_IMAGE=bzimage lapic
root=/dev/sdc1 vga=6
[   73.423729] Local APIC disabled by BIOS -- reenabling.
[   73.423737] Found and enabled local APIC!
[   73.423746] mapped APIC to ffffd000 (fee00000)
[   73.423755] Enabling fast FPU save and restore... done.
[   73.423764] Initializing CPU#0
[   73.423909] CPU 0 irqstacks, hard=c03f3000 soft=c03f2000
[   73.423920] PID hash table entries: 2048 (order: 11, 8192 bytes)
[   73.427064] Console: colour VGA+ 80x60
[   73.429590] Lock dependency validator: Copyright (c) 2006 Red Hat,
Inc., Ingo Molnar
[   73.429743] ... MAX_LOCKDEP_SUBTYPES:    8
[   73.429838] ... MAX_LOCK_DEPTH:          30
[   73.429935] ... MAX_LOCKDEP_KEYS:        2048
[   73.430030] ... TYPEHASH_SIZE:           1024
[   73.430127] ... MAX_LOCKDEP_ENTRIES:     8192
[   73.430222] ... MAX_LOCKDEP_CHAINS:      8192
[   73.430316] ... CHAINHASH_SIZE:          4096
[   73.430411]  memory used by lock dependency info: 696 kB
[   73.430508]  per task-struct memory footprint: 1080 bytes
[   73.430595] ------------------------
[   73.430677] | Locking API testsuite:
[   73.430760] ----------------------------------------------------------------------------
[   73.430894]                                  | spin |wlock |rlock
|mutex | wsem | rsem |
[   73.431030]
--------------------------------------------------------------------------
[   73.431186]                      A-A deadlock:  ok  |  ok  |  ok  |
 ok  |  ok  |  ok  |
[   73.433526]                  A-B-B-A deadlock:  ok  |  ok  |  ok  |
 ok  |  ok  |  ok  |
[   73.435923]              A-B-B-C-C-A deadlock:  ok  |  ok  |  ok  |
 ok  |  ok  |  ok  |
[   73.438304]              A-B-C-A-B-C deadlock:  ok  |  ok  |  ok  |
 ok  |  ok  |  ok  |
[   73.440688]          A-B-B-C-C-D-D-A deadlock:  ok  |  ok  |  ok  |
 ok  |  ok  |  ok  |
[   73.443151]          A-B-C-D-B-D-D-A deadlock:  ok  |  ok  |  ok  |
 ok  |  ok  |  ok  |
[   73.445640]          A-B-C-D-B-C-D-A deadlock:  ok  |  ok  |  ok  |
 ok  |  ok  |  ok  |
[   73.448083]                     double unlock:  ok  |  ok  |  ok  |
 ok  |  ok  |  ok  |
[   73.450360]                  bad unlock order:  ok  |  ok  |  ok  |
 ok  |  ok  |  ok  |
[   73.452675]
--------------------------------------------------------------------------
[   73.452823]               recursive read-lock:             |  ok  |
            |  ok  |
[   73.453768]
--------------------------------------------------------------------------
[   73.453947]                 non-nested unlock:  ok  |  ok  |  ok  |  ok  |
[   73.455518]   ------------------------------------------------------------
[   73.455618]      hard-irqs-on + irq-safe-A/12:  ok  |  ok  |  ok  |
[   73.456799]      soft-irqs-on + irq-safe-A/12:  ok  |  ok  |  ok  |
[   73.457985]      hard-irqs-on + irq-safe-A/21:  ok  |  ok  |  ok  |
[   73.459163]      soft-irqs-on + irq-safe-A/21:  ok  |  ok  |  ok  |
[   73.460340]        sirq-safe-A => hirqs-on/12:  ok  |  ok  |  ok  |
[   73.461532]        sirq-safe-A => hirqs-on/21:  ok  |  ok  |  ok  |
[   73.462723]          hard-safe-A + irqs-on/12:  ok  |  ok  |  ok  |
[   73.463929]          soft-safe-A + irqs-on/12:  ok  |  ok  |  ok  |
[   73.465113]          hard-safe-A + irqs-on/21:  ok  |  ok  |  ok  |
[   73.466299]          soft-safe-A + irqs-on/21:  ok  |  ok  |  ok  |
[   73.467487]     hard-safe-A + unsafe-B #1/123:  ok  |  ok  |  ok  |
[   73.468692]     soft-safe-A + unsafe-B #1/123:  ok  |  ok  |  ok  |
[   73.469907]     hard-safe-A + unsafe-B #1/132:  ok  |  ok  |  ok  |
[   73.471119]     soft-safe-A + unsafe-B #1/132:  ok  |  ok  |  ok  |
[   73.472331]     hard-safe-A + unsafe-B #1/213:  ok  |  ok  |  ok  |
[   73.473538]     soft-safe-A + unsafe-B #1/213:  ok  |  ok  |  ok  |
[   73.474779]     hard-safe-A + unsafe-B #1/231:  ok  |  ok  |  ok  |
[   73.475982]     soft-safe-A + unsafe-B #1/231:  ok  |  ok  |  ok  |
[   73.477182]     hard-safe-A + unsafe-B #1/312:  ok  |  ok  |  ok  |
[   73.478371]     soft-safe-A + unsafe-B #1/312:  ok  |  ok  |  ok  |
[   73.479574]     hard-safe-A + unsafe-B #1/321:  ok  |  ok  |  ok  |
[   73.480780]     soft-safe-A + unsafe-B #1/321:  ok  |  ok  |  ok  |
[   73.481976]     hard-safe-A + unsafe-B #2/123:  ok  |  ok  |  ok  |
[   73.483181]     soft-safe-A + unsafe-B #2/123:  ok  |  ok  |  ok  |
[   73.484423]     hard-safe-A + unsafe-B #2/132:  ok  |  ok  |  ok  |
[   73.485629]     soft-safe-A + unsafe-B #2/132:  ok  |  ok  |  ok  |
[   73.486848]     hard-safe-A + unsafe-B #2/213:  ok  |  ok  |  ok  |
[   73.488061]     soft-safe-A + unsafe-B #2/213:  ok  |  ok  |  ok  |
[   73.489268]     hard-safe-A + unsafe-B #2/231:  ok  |  ok  |  ok  |
[   73.490471]     soft-safe-A + unsafe-B #2/231:  ok  |  ok  |  ok  |
[   73.491680]     hard-safe-A + unsafe-B #2/312:  ok  |  ok  |  ok  |
[   73.492885]     soft-safe-A + unsafe-B #2/312:  ok  |  ok  |  ok  |
[   73.494122]     hard-safe-A + unsafe-B #2/321:  ok  |  ok  |  ok  |
[   73.495334]     soft-safe-A + unsafe-B #2/321:  ok  |  ok  |  ok  |
[   73.496548]       hard-irq lock-inversion/123:  ok  |  ok  |  ok  |
[   73.497751]       soft-irq lock-inversion/123:  ok  |  ok  |  ok  |
[   73.498966]       hard-irq lock-inversion/132:  ok  |  ok  |  ok  |
[   73.500182]       soft-irq lock-inversion/132:  ok  |  ok  |  ok  |
[   73.501394]       hard-irq lock-inversion/213:  ok  |  ok  |  ok  |
[   73.502607]       soft-irq lock-inversion/213:  ok  |  ok  |  ok  |
[   73.503822]       hard-irq lock-inversion/231:  ok  |  ok  |  ok  |
[   73.505056]       soft-irq lock-inversion/231:  ok  |  ok  |  ok  |
[   73.506275]       hard-irq lock-inversion/312:  ok  |  ok  |  ok  |
[   73.507488]       soft-irq lock-inversion/312:  ok  |  ok  |  ok  |
[   73.508720]       hard-irq lock-inversion/321:  ok  |  ok  |  ok  |
[   73.509936]       soft-irq lock-inversion/321:  ok  |  ok  |  ok  |
[   73.511156]       hard-irq read-recursion/123:  ok  |
[   73.511652]       soft-irq read-recursion/123:  ok  |
[   73.512146]       hard-irq read-recursion/132:  ok  |
[   73.512640]       soft-irq read-recursion/132:  ok  |
[   73.513135]       hard-irq read-recursion/213:  ok  |
[   73.513630]       soft-irq read-recursion/213:  ok  |
[   73.514146]       hard-irq read-recursion/231:  ok  |
[   73.514628]       soft-irq read-recursion/231:  ok  |
[   73.515111]       hard-irq read-recursion/312:  ok  |
[   73.515590]       soft-irq read-recursion/312:  ok  |
[   73.516077]       hard-irq read-recursion/321:  ok  |
[   73.516562]       soft-irq read-recursion/321:  ok  |
[   73.517057] -------------------------------------------------------
[   73.517155] Good, all 210 testcases passed! |
[   73.517246] ---------------------------------
[   73.518188] Dentry cache hash table entries: 65536 (order: 6, 262144 bytes)
[   73.519170] Inode-cache hash table entries: 32768 (order: 5, 131072 bytes)
[   73.567701] Memory: 514628k/524224k available (1572k kernel code,
9028k reserved, 909k data, 160k init, 0k highmem)
[   73.567877] Checking if this processor honours the WP bit even in
supervisor mode... Ok.
[   73.713687] Calibrating delay using timer specific routine..
1613.93 BogoMIPS (lpj=8069673)
[   73.714134] Mount-cache hash table entries: 512
[   73.715094] CPU: After generic identify, caps: 0183fbff c1c3fbff
00000000 00000000 00000000 00000000 00000000
[   73.715127] CPU: After vendor identify, caps: 0183fbff c1c3fbff
00000000 00000000 00000000 00000000 00000000
[   73.715159] CPU: L1 I Cache: 64K (64 bytes/line), D cache 64K (64 bytes/line)
[   73.715259] CPU: L2 Cache: 512K (64 bytes/line)
[   73.715345] CPU: After all inits, caps: 0183fbff c1c3fbff 00000000
00000420 00000000 00000000 00000000
[   73.715375] Intel machine check architecture supported.
[   73.715464] Intel machine check reporting enabled on CPU#0.
[   73.715560] Compat vDSO mapped to ffffe000.
[   73.715663] CPU: AMD Athlon(tm) Processor stepping 01
[   73.715818] Checking 'hlt' instruction... OK.
[   73.753770] SMP alternatives: switching to UP code
[   73.753865] Freeing SMP alternatives: 0k freed
[   73.763218] ACPI: setting ELCR to 0010 (from 0e00)
[   73.764030] lockdep: disabled NMI watchdog.
[   73.889610] NET: Registered protocol family 16
[   73.890016] ACPI: bus type pci registered
[   73.902012] PCI: PCI BIOS revision 2.10 entry at 0xfdaf1, last bus=1
[   73.902116] Setting up standard PCI resources
[   73.904737] spurious 8259A interrupt: IRQ7.
[   73.917948] ACPI: Subsystem revision 20060310
[   73.933832] ACPI: Interpreter enabled
[   73.933926] ACPI: Using PIC for interrupt routing
[   73.936924] ACPI: PCI Root Bridge [PCI0] (0000:00)
[   73.937057] PCI: Probing PCI hardware (bus 00)
[   73.946681] Boot video device is 0000:01:05.0
[   73.947042] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0._PRT]
[   73.957760] ACPI: Power Resource [URP1] (off)
[   73.958278] ACPI: Power Resource [URP2] (off)
[   73.958749] ACPI: Power Resource [FDDP] (off)
[   73.959221] ACPI: Power Resource [LPTP] (off)
[   73.961008] ACPI: PCI Interrupt Link [LNKA] (IRQs 3 4 5 6 7 9 *10
11 12 14 15)
[   73.962554] ACPI: PCI Interrupt Link [LNKB] (IRQs 3 4 5 6 7 9 10
*11 12 14 15)
[   73.964102] ACPI: PCI Interrupt Link [LNKC] (IRQs 3 4 5 6 7 *9 10
11 12 14 15)
[   73.965597] ACPI: PCI Interrupt Link [LNKD] (IRQs 3 4 5 6 7 9 10 11
12 14 15) *0, disabled.
[   73.966646] Linux Plug and Play Support v0.97 (c) Adam Belay
[   73.966851] pnp: PnP ACPI init
[   73.973130] pnp: PnP ACPI: found 8 devices
[   73.973242] PnPBIOS: Disabled by ACPI PNP
[   73.974372] SCSI subsystem initialized
[   73.974759] PCI: Using ACPI for IRQ routing
[   73.974867] PCI: If a device doesn't work, try "pci=routeirq".  If
it helps, post a report
[   73.986036] PCI: Bridge: 0000:00:01.0
[   73.986144]   IO window: 9000-9fff
[   73.986267]   MEM window: e7d00000-efdfffff
[   73.986376]   PREFETCH window: e3b00000-e3bfffff
[   73.986638] NET: Registered protocol family 2
[   74.083678] IP route cache hash table entries: 4096 (order: 2, 16384 bytes)
[   74.084451] TCP established hash table entries: 16384 (order: 8,
1376256 bytes)
[   74.092659] TCP bind hash table entries: 8192 (order: 7, 720896 bytes)
[   74.097170] TCP: Hash tables configured (established 16384 bind 8192)
[   74.097333] TCP reno registered
[   74.099775] Machine check exception polling timer started.
[   74.105643] Initializing Cryptographic API
[   74.105781] io scheduler noop registered
[   74.105959] io scheduler cfq registered (default)
[   74.106509] ACPI: Power Button (FF) [PWRF]
[   74.106627] ACPI: Sleep Button (FF) [SLPF]
[   74.106745] ACPI: Power Button (CM) [PWRB]
[   74.107319] isapnp: Scanning for PnP cards...
[   74.464326] isapnp: No Plug & Play device found
[   74.481654] Floppy drive(s): fd0 is 1.44M
[   74.495209] FDC 0 is a post-1991 82077
[   74.498173] libata version 1.30 loaded.
[   74.498489] pata_pdc2027x 0000:00:0a.0: version 0.74
[   74.499315] ACPI: PCI Interrupt Link [LNKB] enabled at IRQ 11
[   74.499430] PCI: setting IRQ 11 as level-triggered
[   74.499440] ACPI: PCI Interrupt 0000:00:0a.0[A] -> Link [LNKB] ->
GSI 11 (level, low) -> IRQ 11
[   74.599821] pata_pdc2027x 0000:00:0a.0: PLL input clock 16813 kHz
[   74.630253] ata1: PATA max UDMA/133 cmd 0xE08097C0 ctl 0xE0809FDA
bmdma 0xE0809000 irq 11
[   74.630582] ata2: PATA max UDMA/133 cmd 0xE08095C0 ctl 0xE0809DDA
bmdma 0xE0809008 irq 11
[   74.783656] ata1.00: cfg 49:2f00 82:7c6b 83:7f09 84:4003 85:7c69
86:3e01 87:4003 88:407f
[   74.783672] ata1.00: ATA-7, max UDMA/133, 490234752 sectors: LBA48
[   74.784639] ata1.00: configured for UDMA/133
[   74.784736] scsi0 : pata_pdc2027x
[   74.943624] ata2.00: cfg 49:2f00 82:346b 83:7f01 84:4003 85:3469
86:3c01 87:4003 88:203f
[   74.943638] ata2.00: ATA-6, max UDMA/100, 625142448 sectors: LBA48
[   74.944727] ata2.00: configured for UDMA/100
[   74.944827] scsi1 : pata_pdc2027x
[   74.946048]   Vendor: ATA       Model: Maxtor 6Y250P0    Rev: YAR4
[   74.947132]   Type:   Direct-Access                      ANSI SCSI
revision: 05
[   74.948531]   Vendor: ATA       Model: WDC WD3200JB-00K  Rev: 08.0
[   74.949587]   Type:   Direct-Access                      ANSI SCSI
revision: 05
[   74.950858] sata_sil 0000:00:0d.0: version 1.0
[   74.951608] ACPI: PCI Interrupt Link [LNKA] enabled at IRQ 10
[   74.951721] PCI: setting IRQ 10 as level-triggered
[   74.951731] ACPI: PCI Interrupt 0000:00:0d.0[A] -> Link [LNKA] ->
GSI 10 (level, low) -> IRQ 10
[   74.952000] sata_sil 0000:00:0d.0: Applying R_ERR on DMA activate
FIS errata fix
[   74.952353] ata3: SATA max UDMA/100 cmd 0xE080E480 ctl 0xE080E48A
bmdma 0xE080E400 irq 10
[   74.952744] ata4: SATA max UDMA/100 cmd 0xE080E4C0 ctl 0xE080E4CA
bmdma 0xE080E408 irq 10
[   74.953057] ata5: SATA max UDMA/100 cmd 0xE080E680 ctl 0xE080E68A
bmdma 0xE080E600 irq 10
[   74.953387] ata6: SATA max UDMA/100 cmd 0xE080E6C0 ctl 0xE080E6CA
bmdma 0xE080E608 irq 10
[   75.322421] ata3: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
[   75.323384] ata3.00: cfg 49:2f00 82:7c6b 83:7f09 84:4003 85:7c69
86:3e01 87:4003 88:207f
[   75.323400] ata3.00: ATA-7, max UDMA/133, 585940320 sectors: LBA48
[   75.323492] ata3.00: applying bridge limits
[   75.324594] ata3.00: configured for UDMA/100
[   75.324694] scsi2 : sata_sil
[   75.692121] ata4: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
[   75.693397] ata4.00: cfg 49:2f00 82:346b 83:7d01 84:4023 85:3469
86:3c01 87:4023 88:203f
[   75.693410] ata4.00: ATA-7, max UDMA/100, 781422768 sectors: LBA48
[   75.693513] ata4.00: applying bridge limits
[   75.694898] ata4.00: configured for UDMA/100
[   75.694996] scsi3 : sata_sil
[   76.061822] ata5: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
[   76.062791] ata5.00: cfg 49:2f00 82:346b 83:7f01 84:4003 85:3469
86:3e01 87:4003 88:203f
[   76.062805] ata5.00: ATA-6, max UDMA/100, 625142448 sectors: LBA48
[   76.062906] ata5.00: applying bridge limits
[   76.063980] ata5.00: configured for UDMA/100
[   76.064076] scsi4 : sata_sil
[   76.271637] ata6: SATA link down (SStatus 0 SControl 310)
[   76.271756] scsi5 : sata_sil
[   76.272693]   Vendor: ATA       Model: Maxtor 4A300J0    Rev: RAMB
[   76.273756]   Type:   Direct-Access                      ANSI SCSI
revision: 05
[   76.275160]   Vendor: ATA       Model: ST3400832A        Rev: 3.01
[   76.276243]   Type:   Direct-Access                      ANSI SCSI
revision: 05
[   76.277685]   Vendor: ATA       Model: WDC WD3200JB-00K  Rev: 08.0
[   76.278717]   Type:   Direct-Access                      ANSI SCSI
revision: 05
[   76.280592] SCSI device sda: 490234752 512-byte hdwr sectors (251000 MB)
[   76.280796] sda: Write Protect is off
[   76.280900] sda: Mode Sense: 00 3a 00 00
[   76.281068] SCSI device sda: drive cache: write back
[   76.281711] SCSI device sda: 490234752 512-byte hdwr sectors (251000 MB)
[   76.281919] sda: Write Protect is off
[   76.282019] sda: Mode Sense: 00 3a 00 00
[   76.282214] SCSI device sda: drive cache: write back
[   76.282312]  sda: unknown partition table
[   76.284598] sd 0:0:0:0: Attached scsi disk sda
[   76.285234] SCSI device sdb: 625142448 512-byte hdwr sectors (320073 MB)
[   76.285426] sdb: Write Protect is off
[   76.285521] sdb: Mode Sense: 00 3a 00 00
[   76.285687] SCSI device sdb: drive cache: write back
[   76.286193] SCSI device sdb: 625142448 512-byte hdwr sectors (320073 MB)
[   76.286393] sdb: Write Protect is off
[   76.286491] sdb: Mode Sense: 00 3a 00 00
[   76.286680] SCSI device sdb: drive cache: write back
[   76.286787]  sdb: unknown partition table
[   76.290732] sd 1:0:0:0: Attached scsi disk sdb
[   76.291330] SCSI device sdc: 585940320 512-byte hdwr sectors (300001 MB)
[   76.291521] sdc: Write Protect is off
[   76.291654] sdc: Mode Sense: 00 3a 00 00
[   76.291827] SCSI device sdc: drive cache: write back
[   76.292338] SCSI device sdc: 585940320 512-byte hdwr sectors (300001 MB)
[   76.292542] sdc: Write Protect is off
[   76.292640] sdc: Mode Sense: 00 3a 00 00
[   76.292830] SCSI device sdc: drive cache: write back
[   76.292932]  sdc: sdc1
[   76.295994] sd 2:0:0:0: Attached scsi disk sdc
[   76.296559] SCSI device sdd: 781422768 512-byte hdwr sectors (400088 MB)
[   76.296750] sdd: Write Protect is off
[   76.296855] sdd: Mode Sense: 00 3a 00 00
[   76.297021] SCSI device sdd: drive cache: write back
[   76.297532] SCSI device sdd: 781422768 512-byte hdwr sectors (400088 MB)
[   76.297732] sdd: Write Protect is off
[   76.297838] sdd: Mode Sense: 00 3a 00 00
[   76.298029] SCSI device sdd: drive cache: write back
[   76.298125]  sdd: unknown partition table
[   76.318711] sd 3:0:0:0: Attached scsi disk sdd
[   76.319289] SCSI device sde: 625142448 512-byte hdwr sectors (320073 MB)
[   76.319486] sde: Write Protect is off
[   76.319585] sde: Mode Sense: 00 3a 00 00
[   76.319753] SCSI device sde: drive cache: write back
[   76.320256] SCSI device sde: 625142448 512-byte hdwr sectors (320073 MB)
[   76.320459] sde: Write Protect is off
[   76.320556] sde: Mode Sense: 00 3a 00 00
[   76.320744] SCSI device sde: drive cache: write back
[   76.320845]  sde: sde1 sde2
[   76.345135] sd 4:0:0:0: Attached scsi disk sde
[   76.348042] PNP: PS/2 Controller [PNP0303:PS2K,PNP0f03:PS2M] at
0x60,0x64 irq 1,12
[   76.348939] serio: i8042 AUX port at 0x60,0x64 irq 12
[   76.349085] serio: i8042 KBD port at 0x60,0x64 irq 1
[   76.350900] mice: PS/2 mouse device common for all mice
[   76.351297] NET: Registered protocol family 1
[   76.351434] Using IPI Shortcut mode
[   76.351560] Time: tsc clocksource has been installed.
[   76.352398] ACPI: (supports S0 S1 S4 S5)
[   76.353382] Freeing unused kernel memory: 160k freed
[   76.353666] Write protecting the kernel read-only data: 312k
[   76.367030] ReiserFS: sdc1: found reiserfs format "3.6" with standard journal
[   76.386846] input: AT Translated Set 2 keyboard as /class/input/input0
[   76.562009] logips2pp: Detected unknown logitech mouse model 0
[   77.082794] input: PS/2 Logitech Mouse as /class/input/input1
[   94.743067] ReiserFS: sdc1: using ordered data mode
[   94.776394] ReiserFS: sdc1: journal params: device sdc1, size 8192,
journal first block 18, max trans len 1024, max batch 900, max commit
age 30, max trans age 30
[   94.779773] ReiserFS: sdc1: checking transaction log (sdc1)
[   94.876353] ReiserFS: sdc1: Using r5 hash to sort names
[  102.593054] Real Time Clock Driver v1.12ac
[  105.344061] Linux Tulip driver version 1.1.13-NAPI (December 15, 2004)
[  105.345362] ACPI: PCI Interrupt Link [LNKC] enabled at IRQ 9
[  105.345473] PCI: setting IRQ 9 as level-triggered
[  105.345483] ACPI: PCI Interrupt 0000:00:0b.0[A] -> Link [LNKC] ->
GSI 9 (level, low) -> IRQ 9
[  105.361941] tulip0:  EEPROM default media type Autosense.
[  105.362049] tulip0:  Index #0 - Media MII (#11) described by a
21142 MII PHY (3) block.
[  105.366477] tulip0:  MII transceiver #1 config 1000 status 782d
advertising 01e1.
[  105.371705] eth0: Digital DS21143 Tulip rev 65 at 0001d000,
00:C0:F0:4A:0C:46, IRQ 9.
[  105.396983] pcnet32.c:v1.32 18.Mar.2006 tsbogend@alpha.franken.de
[  105.495725] NET: Registered protocol family 5
[  105.589618] ns83820.c: National Semiconductor DP83820 10/100/1000 driver.
[  105.590217] ACPI: PCI Interrupt 0000:00:09.0[A] -> Link [LNKA] ->
GSI 10 (level, low) -> IRQ 10
[  105.590542] eth1: ns83820.c: 0x22c: 00000000, subsystem: 0000:0000
[  105.617982] eth1: ns83820 v0.23: DP83820 v1.2: 00:4f:4a:00:13:5a
io=0xefffb000 irq=10 f=sg
[  106.262717] Loading Reiser4. See www.namesys.com for a description
of Reiser4.
[  139.032547] JFS: nTxBlock = 4023, nTxLock = 32185
[  157.143387] Installing knfsd (copyright (C) 1996 okir@monad.swb.de).
[  158.625829] eth1: link now 1000 mbps, full duplex and up.
[  161.533134] eth0: Setting full-duplex based on MII#1 link partner
capability of cde1.
[  170.556683] NFSD: Using /var/lib/nfs/v4recovery as the NFSv4 state
recovery directory
[  170.558038] NFSD: starting 90-second grace period
[ 1637.890434]
[ 1637.890440] ======================================
[ 1637.890641] [ BUG: bad unlock ordering detected! ]
[ 1637.890741] --------------------------------------
[ 1637.890841] mv/935 is trying to release lock (&mgr->tmgr_lock) at:
[ 1637.890996]  [<e098e01b>] try_capture+0x306/0x9b1 [reiser4]
[ 1637.891255] but the next lock to release is:
[ 1637.891344]  (&atom->alock){--..}, at: [<e098dfe2>]
try_capture+0x2cd/0x9b1 [reiser4]
[ 1637.891667]
[ 1637.891670] other info that might help us debug this:
[ 1637.891854] 3 locks held by mv/935:
[ 1637.891951]  #0:  (&inode->i_mutex/1){--..}, at: [<c0160325>]
lock_rename+0xba/0xc1
[ 1637.892297]  #1:  (&mgr->tmgr_lock){--..}, at: [<e098deb5>]
try_capture+0x1a0/0x9b1 [reiser4]
[ 1637.892647]  #2:  (&txnh->hlock){--..}, at: [<e098debd>]
try_capture+0x1a8/0x9b1 [reiser4]
[ 1637.892994]
[ 1637.892996] stack backtrace:
[ 1637.893577]  [<c010311a>] show_trace_log_lvl+0x54/0xfd
[ 1637.893738]  [<c0103709>] show_trace+0xd/0x10
[ 1637.893893]  [<c0103750>] dump_stack+0x19/0x1b
[ 1637.894045]  [<c012d713>] lockdep_release+0x18b/0x350
[ 1637.894407]  [<c02880d9>] _spin_unlock+0x16/0x1f
[ 1637.894777]  [<e098e01b>] try_capture+0x306/0x9b1 [reiser4]
[ 1637.895048]  [<e0988a80>] longterm_lock_znode+0x2e3/0x3e3 [reiser4]
[ 1637.895254]  [<e0995790>] coord_by_handle+0x136/0xaf4 [reiser4]
[ 1637.895515]  [<e09962de>] object_lookup+0x8e/0x96 [reiser4]
[ 1637.895764]  [<e09a9ece>] find_entry+0xbb/0x200 [reiser4]
[ 1637.896134]  [<e099fab1>] rename_common+0x96b/0x9b6 [reiser4]
[ 1637.896440]  [<c0160e96>] vfs_rename+0x1dd/0x315
[ 1637.897098]  [<c0162b84>] sys_renameat+0x1bb/0x22a
[ 1637.897664]  [<c0162c05>] sys_rename+0x12/0x14
[ 1637.898220]  [<c0288283>] syscall_call+0x7/0xb

Re: 2.6.17-rc5-mm3: bad unlock ordering (reiser4?)

[Barry K. Nathan]

On 6/4/06, Barry K. Nathan <barryn@pobox.com> wrote:
> This is 2.6.17-rc5-mm3 + the 3 ns83820 patches. I have no idea what I
> did to cause this to happen (i.e. it claims that mv is the culprit,
> but I don't think I was running mv myself -- I guess it was spawned by
> another process, but I have *no* idea what would have done it). I'm
> including the full dmesg.

Ok, I got another similar-looking one, with 2.6.17-rc5-mm3 plus
lockdep-combo and lockdep-tracer. (Again, the full dmesg is at the
bottom of this message.) This time I know what I was doing. The
reiser4 filesystem was being served using Samba, and I mounted it from
another Linux box using cifs. I was copying a single, large
(multi-hundred-MB) file from the cifs client to the Samba server.
However, the morning cronjobs were probably running at the same time.
Anyway, my gut feeling is that I will be able to reproduce this easily
(although I haven't tried again yet).

The /proc/latency_trace, in case it helps, is here:
http://members.cox.net/barrykn/linux/trace/latency_trace_reiser4-2.bz2

It's about the same size as the previous latency_trace (both
compressed and decompressed).

BTW, I also tried 2.6.17-rc5-mm3 (with no other patches) on another
box of mine, running Ubuntu Dapper Drake. (It was installed with one
of the flights but has been updated to the final release.) It got hit
with a flood of scheduling-while-atomic BUGs when either suspending to
disk or resuming, and eth0 didn't come back up automatically as usual
-- I had to manually modprobe r8169 and then run
"/etc/init.d/networking restart" to get to the outside world again. I
might not be able to provide a more detailed report on this box for
another day or two.
-- 
-Barry K. Nathan <barryn@pobox.com>

[    0.000000] Linux version 2.6.17-rc5-mm3-lockdep (barryn@nserv)
(gcc version 4.1.1) #1 Sun Jun 4 05:47:13 PDT 2006
[    0.000000] BIOS-provided physical RAM map:
[    0.000000] sanitize start
[    0.000000] sanitize end
[    0.000000] copy_e820_map() start: 0000000000000000 size:
000000000009fc00 end: 000000000009fc00 type: 1
[    0.000000] copy_e820_map() type is E820_RAM
[    0.000000] add_memory_region(0000000000000000, 000000000009fc00, 1)
[    0.000000] copy_e820_map() start: 000000000009fc00 size:
0000000000000400 end: 00000000000a0000 type: 2
[    0.000000] add_memory_region(000000000009fc00, 0000000000000400, 2)
[    0.000000] copy_e820_map() start: 00000000000f0000 size:
0000000000010000 end: 0000000000100000 type: 2
[    0.000000] add_memory_region(00000000000f0000, 0000000000010000, 2)
[    0.000000] copy_e820_map() start: 0000000000100000 size:
000000001fef0000 end: 000000001fff0000 type: 1
[    0.000000] copy_e820_map() type is E820_RAM
[    0.000000] add_memory_region(0000000000100000, 000000001fef0000, 1)
[    0.000000] copy_e820_map() start: 000000001fff0000 size:
0000000000008000 end: 000000001fff8000 type: 3
[    0.000000] add_memory_region(000000001fff0000, 0000000000008000, 3)
[    0.000000] copy_e820_map() start: 000000001fff8000 size:
0000000000008000 end: 0000000020000000 type: 4
[    0.000000] add_memory_region(000000001fff8000, 0000000000008000, 4)
[    0.000000] copy_e820_map() start: 00000000ffff0000 size:
0000000000010000 end: 0000000100000000 type: 2
[    0.000000] add_memory_region(00000000ffff0000, 0000000000010000, 2)
[    0.000000]  BIOS-e820: 0000000000000000 - 000000000009fc00 (usable)
[    0.000000]  BIOS-e820: 000000000009fc00 - 00000000000a0000 (reserved)
[    0.000000]  BIOS-e820: 00000000000f0000 - 0000000000100000 (reserved)
[    0.000000]  BIOS-e820: 0000000000100000 - 000000001fff0000 (usable)
[    0.000000]  BIOS-e820: 000000001fff0000 - 000000001fff8000 (ACPI data)
[    0.000000]  BIOS-e820: 000000001fff8000 - 0000000020000000 (ACPI NVS)
[    0.000000]  BIOS-e820: 00000000ffff0000 - 0000000100000000 (reserved)
[    0.000000] 511MB LOWMEM available.
[    0.000000] On node 0 totalpages: 131056
[    0.000000]   DMA zone: 4096 pages, LIFO batch:0
[    0.000000]   Normal zone: 126960 pages, LIFO batch:31
[    0.000000] DMI 2.3 present.
[    0.000000] ACPI: RSDP (v000 AMI
) @ 0x000fa8f0
[    0.000000] ACPI: RSDT (v001 AMIINT          0x00000010 MSFT
0x00000097) @ 0x1fff0000
[    0.000000] ACPI: FADT (v001 AMIINT          0x00000010 MSFT
0x00000097) @ 0x1fff0030
[    0.000000] ACPI: DSDT (v001 AMD75X IRONGATE 0x00001000 MSFT
0x0100000b) @ 0x00000000
[    0.000000] Allocating PCI resources starting at 30000000 (gap:
20000000:dfff0000)
[    0.000000] Detected 805.703 MHz processor.
[   76.535150] Built 1 zonelists
[   76.535189] Kernel command line: BOOT_IMAGE=bzimage lapic
root=/dev/sdc1 vga=6
[   76.540794] Local APIC disabled by BIOS -- reenabling.
[   76.540848] Found and enabled local APIC!
[   76.540896] mapped APIC to ffffd000 (fee00000)
[   76.540952] Enabling fast FPU save and restore... done.
[   76.541019] Initializing CPU#0
[   76.541506] CPU 0 irqstacks, hard=c0440000 soft=c043f000
[   76.541561] PID hash table entries: 2048 (order: 11, 8192 bytes)
[   76.544932] Console: colour VGA+ 80x60
[   76.549033] Lock dependency validator: Copyright (c) 2006 Red Hat,
Inc., Ingo Molnar
[   76.549273] ... MAX_LOCKDEP_SUBTYPES:    8
[   76.549428] ... MAX_LOCK_DEPTH:          30
[   76.549582] ... MAX_LOCKDEP_KEYS:        2048
[   76.549739] ... TYPEHASH_SIZE:           1024
[   76.549897] ... MAX_LOCKDEP_ENTRIES:     8192
[   76.550055] ... MAX_LOCKDEP_CHAINS:      8192
[   76.550215] ... CHAINHASH_SIZE:          4096
[   76.550372]  memory used by lock dependency info: 696 kB
[   76.550536]  per task-struct memory footprint: 1080 bytes
[   76.550699] starting custom tracer.
[   76.550858] ------------------------
[   76.551012] | Locking API testsuite:
[   76.551167] ----------------------------------------------------------------------------
[   76.551406]                                  | spin |wlock |rlock
|mutex | wsem | rsem |
[   76.551785]
--------------------------------------------------------------------------
[   76.552097]                      A-A deadlock:  ok  |  ok  |  ok  |
 ok  |  ok  |  ok  |
[   76.555608]                  A-B-B-A deadlock:  ok  |  ok  |  ok  |
 ok  |  ok  |  ok  |
[   76.559221]              A-B-B-C-C-A deadlock:  ok  |  ok  |  ok  |
 ok  |  ok  |  ok  |
[   76.563227]              A-B-C-A-B-C deadlock:  ok  |  ok  |  ok  |
 ok  |  ok  |  ok  |
[   76.567053]          A-B-B-C-C-D-D-A deadlock:  ok  |  ok  |  ok  |
 ok  |  ok  |  ok  |
[   76.571173]          A-B-C-D-B-D-D-A deadlock:  ok  |  ok  |  ok  |
 ok  |  ok  |  ok  |
[   76.575341]          A-B-C-D-B-C-D-A deadlock:  ok  |  ok  |  ok  |
 ok  |  ok  |  ok  |
[   76.579436]                     double unlock:  ok  |  ok  |  ok  |
 ok  |  ok  |  ok  |
[   76.582972]                  bad unlock order:  ok  |  ok  |  ok  |
 ok  |  ok  |  ok  |
[   76.586516]
--------------------------------------------------------------------------
[   76.586758]               recursive read-lock:             |  ok  |
            |  ok  |
[   76.588229]
--------------------------------------------------------------------------
[   76.588463]                 non-nested unlock:  ok  |  ok  |  ok  |  ok  |
[   76.590926]   ------------------------------------------------------------
[   76.591108]      hard-irqs-on + irq-safe-A/12:  ok  |  ok  |  ok  |
[   76.593023]      soft-irqs-on + irq-safe-A/12:  ok  |  ok  |  ok  |
[   76.594856]      hard-irqs-on + irq-safe-A/21:  ok  |  ok  |  ok  |
[   76.596658]      soft-irqs-on + irq-safe-A/21:  ok  |  ok  |  ok  |
[   76.598482]        sirq-safe-A => hirqs-on/12:  ok  |  ok  |  ok  |
[   76.600323]        sirq-safe-A => hirqs-on/21:  ok  |  ok  |  ok  |
[   76.602260]          hard-safe-A + irqs-on/12:  ok  |  ok  |  ok  |
[   76.604064]          soft-safe-A + irqs-on/12:  ok  |  ok  |  ok  |
[   76.605908]          hard-safe-A + irqs-on/21:  ok  |  ok  |  ok  |
[   76.607713]          soft-safe-A + irqs-on/21:  ok  |  ok  |  ok  |
[   76.609549]     hard-safe-A + unsafe-B #1/123:  ok  |  ok  |  ok  |
[   76.611588]     soft-safe-A + unsafe-B #1/123:  ok  |  ok  |  ok  |
[   76.613517]     hard-safe-A + unsafe-B #1/132:  ok  |  ok  |  ok  |
[   76.615419]     soft-safe-A + unsafe-B #1/132:  ok  |  ok  |  ok  |
[   76.617337]     hard-safe-A + unsafe-B #1/213:  ok  |  ok  |  ok  |
[   76.619248]     soft-safe-A + unsafe-B #1/213:  ok  |  ok  |  ok  |
[   76.621177]     hard-safe-A + unsafe-B #1/231:  ok  |  ok  |  ok  |
[   76.623177]     soft-safe-A + unsafe-B #1/231:  ok  |  ok  |  ok  |
[   76.625070]     hard-safe-A + unsafe-B #1/312:  ok  |  ok  |  ok  |
[   76.626916]     soft-safe-A + unsafe-B #1/312:  ok  |  ok  |  ok  |
[   76.628781]     hard-safe-A + unsafe-B #1/321:  ok  |  ok  |  ok  |
[   76.630668]     soft-safe-A + unsafe-B #1/321:  ok  |  ok  |  ok  |
[   76.632648]     hard-safe-A + unsafe-B #2/123:  ok  |  ok  |  ok  |
[   76.634562]     soft-safe-A + unsafe-B #2/123:  ok  |  ok  |  ok  |
[   76.636490]     hard-safe-A + unsafe-B #2/132:  ok  |  ok  |  ok  |
[   76.638387]     soft-safe-A + unsafe-B #2/132:  ok  |  ok  |  ok  |
[   76.640337]     hard-safe-A + unsafe-B #2/213:  ok  |  ok  |  ok  |
[   76.642356]     soft-safe-A + unsafe-B #2/213:  ok  |  ok  |  ok  |
[   76.644281]     hard-safe-A + unsafe-B #2/231:  ok  |  ok  |  ok  |
[   76.646175]     soft-safe-A + unsafe-B #2/231:  ok  |  ok  |  ok  |
[   76.648122]     hard-safe-A + unsafe-B #2/312:  ok  |  ok  |  ok  |
[   76.650013]     soft-safe-A + unsafe-B #2/312:  ok  |  ok  |  ok  |
[   76.652052]     hard-safe-A + unsafe-B #2/321:  ok  |  ok  |  ok  |
[   76.653938]     soft-safe-A + unsafe-B #2/321:  ok  |  ok  |  ok  |
[   76.655872]       hard-irq lock-inversion/123:  ok  |  ok  |  ok  |
[   76.657795]       soft-irq lock-inversion/123:  ok  |  ok  |  ok  |
[   76.659723]       hard-irq lock-inversion/132:  ok  |  ok  |  ok  |
[   76.661740]       soft-irq lock-inversion/132:  ok  |  ok  |  ok  |
[   76.663685]       hard-irq lock-inversion/213:  ok  |  ok  |  ok  |
[   76.665599]       soft-irq lock-inversion/213:  ok  |  ok  |  ok  |
[   76.667557]       hard-irq lock-inversion/231:  ok  |  ok  |  ok  |
[   76.669433]       soft-irq lock-inversion/231:  ok  |  ok  |  ok  |
[   76.671355]       hard-irq lock-inversion/312:  ok  |  ok  |  ok  |
[   76.673369]       soft-irq lock-inversion/312:  ok  |  ok  |  ok  |
[   76.675316]       hard-irq lock-inversion/321:  ok  |  ok  |  ok  |
[   76.677235]       soft-irq lock-inversion/321:  ok  |  ok  |  ok  |
[   76.679157]       hard-irq read-recursion/123:  ok  |
[   76.679950]       soft-irq read-recursion/123:  ok  |
[   76.680754]       hard-irq read-recursion/132:  ok  |
[   76.681667]       soft-irq read-recursion/132:  ok  |
[   76.682475]       hard-irq read-recursion/213:  ok  |
[   76.683275]       soft-irq read-recursion/213:  ok  |
[   76.684081]       hard-irq read-recursion/231:  ok  |
[   76.684869]       soft-irq read-recursion/231:  ok  |
[   76.685674]       hard-irq read-recursion/312:  ok  |
[   76.686456]       soft-irq read-recursion/312:  ok  |
[   76.687245]       hard-irq read-recursion/321:  ok  |
[   76.688023]       soft-irq read-recursion/321:  ok  |
[   76.688823] -------------------------------------------------------
[   76.688997] Good, all 210 testcases passed! |
[   76.689153] ---------------------------------
[   76.690197] Dentry cache hash table entries: 65536 (order: 6, 262144 bytes)
[   76.692043] Inode-cache hash table entries: 32768 (order: 5, 131072 bytes)
[   76.835269] Memory: 501872k/524224k available (1649k kernel code,
21764k reserved, 912k data, 164k init, 0k highmem)
[   76.835541] Checking if this processor honours the WP bit even in
supervisor mode... Ok.
[   76.981271] Calibrating delay using timer specific routine..
1630.05 BogoMIPS (lpj=8150286)
[   76.982966] Mount-cache hash table entries: 512
[   76.987564] CPU: After generic identify, caps: 0183fbff c1c3fbff
00000000 00000000 00000000 00000000 00000000
[   76.987783] CPU: After vendor identify, caps: 0183fbff c1c3fbff
00000000 00000000 00000000 00000000 00000000
[   76.988001] CPU: L1 I Cache: 64K (64 bytes/line), D cache 64K (64 bytes/line)
[   76.988183] CPU: L2 Cache: 512K (64 bytes/line)
[   76.988335] CPU: After all inits, caps: 0183fbff c1c3fbff 00000000
00000420 00000000 00000000 00000000
[   76.988545] Intel machine check architecture supported.
[   76.988716] Intel machine check reporting enabled on CPU#0.
[   76.988901] Compat vDSO mapped to ffffe000.
[   76.989092] CPU: AMD Athlon(tm) Processor stepping 01
[   76.989401] Checking 'hlt' instruction... OK.
[   77.021381] SMP alternatives: switching to UP code
[   77.021540] Freeing SMP alternatives: 0k freed
[   77.070957] ACPI: setting ELCR to 0010 (from 0e00)
[   77.073064] lockdep: disabled NMI watchdog.
[   77.201147] spurious 8259A interrupt: IRQ7.
[   77.211879] NET: Registered protocol family 16
[   77.213689] ACPI: bus type pci registered
[   77.225846] PCI: PCI BIOS revision 2.10 entry at 0xfdaf1, last bus=1
[   77.228501] Setting up standard PCI resources
[   77.246716] ACPI: Subsystem revision 20060310
[   77.368439] ACPI: Interpreter enabled
[   77.368609] ACPI: Using PIC for interrupt routing
[   77.386424] ACPI: PCI Root Bridge [PCI0] (0000:00)
[   77.386649] PCI: Probing PCI hardware (bus 00)
[   77.461011] Boot video device is 0000:01:05.0
[   77.462264] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0._PRT]
[   77.544169] ACPI: Power Resource [URP1] (off)
[   77.547068] ACPI: Power Resource [URP2] (off)
[   77.549694] ACPI: Power Resource [FDDP] (off)
[   77.552692] ACPI: Power Resource [LPTP] (off)
[   77.565425] ACPI: PCI Interrupt Link [LNKA] (IRQs 3 4 5 6 7 9 *10
11 12 14 15)
[   77.575014] ACPI: PCI Interrupt Link [LNKB] (IRQs 3 4 5 6 7 9 10
*11 12 14 15)
[   77.584216] ACPI: PCI Interrupt Link [LNKC] (IRQs 3 4 5 6 7 *9 10
11 12 14 15)
[   77.593666] ACPI: PCI Interrupt Link [LNKD] (IRQs 3 4 5 6 7 9 10 11
12 14 15) *0, disabled.
[   77.597972] Linux Plug and Play Support v0.97 (c) Adam Belay
[   77.598827] pnp: PnP ACPI init
[   77.648262] pnp: PnP ACPI: found 8 devices
[   77.648443] PnPBIOS: Disabled by ACPI PNP
[   77.653805] SCSI subsystem initialized
[   77.655803] PCI: Using ACPI for IRQ routing
[   77.655964] PCI: If a device doesn't work, try "pci=routeirq".  If
it helps, post a report
[   77.682073] PCI: Bridge: 0000:00:01.0
[   77.682275]   IO window: 9000-9fff
[   77.682518]   MEM window: e7d00000-efdfffff
[   77.682734]   PREFETCH window: e3b00000-e3bfffff
[   77.683554] NET: Registered protocol family 2
[   77.771843] IP route cache hash table entries: 4096 (order: 2, 16384 bytes)
[   77.774955] TCP established hash table entries: 16384 (order: 8,
1376256 bytes)
[   77.812319] TCP bind hash table entries: 8192 (order: 7, 720896 bytes)
[   77.831296] TCP: Hash tables configured (established 16384 bind 8192)
[   77.831546] TCP reno registered
[   77.844893] Machine check exception polling timer started.
[   77.880040] Initializing Cryptographic API
[   77.880301] io scheduler noop registered
[   77.881456] io scheduler cfq registered (default)
[   77.883887] ACPI: Power Button (FF) [PWRF]
[   77.884205] ACPI: Sleep Button (FF) [SLPF]
[   77.884462] ACPI: Power Button (CM) [PWRB]
[   77.887221] isapnp: Scanning for PnP cards...
[   78.251873] isapnp: No Plug & Play device found
[   78.358986] Floppy drive(s): fd0 is 1.44M
[   78.373335] FDC 0 is a post-1991 82077
[   78.386355] libata version 1.30 loaded.
[   78.388082] pata_pdc2027x 0000:00:0a.0: version 0.74
[   78.393944] ACPI: PCI Interrupt Link [LNKB] enabled at IRQ 11
[   78.394133] PCI: setting IRQ 11 as level-triggered
[   78.394184] ACPI: PCI Interrupt 0000:00:0a.0[A] -> Link [LNKB] ->
GSI 11 (level, low) -> IRQ 11
[   78.496118] pata_pdc2027x 0000:00:0a.0: PLL input clock 17028 kHz
[   78.527655] ata1: PATA max UDMA/133 cmd 0xE08097C0 ctl 0xE0809FDA
bmdma 0xE0809000 irq 11
[   78.528764] ata2: PATA max UDMA/133 cmd 0xE08095C0 ctl 0xE0809DDA
bmdma 0xE0809008 irq 11
[   78.681066] ata1.00: cfg 49:2f00 82:7c6b 83:7f09 84:4003 85:7c69
86:3e01 87:4003 88:407f
[   78.681145] ata1.00: ATA-7, max UDMA/133, 490234752 sectors: LBA48
[   78.682645] ata1.00: configured for UDMA/133
[   78.682815] scsi0 : pata_pdc2027x
[   78.840984] ata2.00: cfg 49:2f00 82:346b 83:7f01 84:4003 85:3469
86:3c01 87:4003 88:203f
[   78.841060] ata2.00: ATA-6, max UDMA/100, 625142448 sectors: LBA48
[   78.842694] ata2.00: configured for UDMA/100
[   78.842859] scsi1 : pata_pdc2027x
[   78.848704]   Vendor: ATA       Model: Maxtor 6Y250P0    Rev: YAR4
[   78.851042]   Type:   Direct-Access                      ANSI SCSI
revision: 05
[   78.858736]   Vendor: ATA       Model: WDC WD3200JB-00K  Rev: 08.0
[   78.861130]   Type:   Direct-Access                      ANSI SCSI
revision: 05
[   78.868271] sata_sil 0000:00:0d.0: version 1.0
[   78.874050] ACPI: PCI Interrupt Link [LNKA] enabled at IRQ 10
[   78.874255] PCI: setting IRQ 10 as level-triggered
[   78.874308] ACPI: PCI Interrupt 0000:00:0d.0[A] -> Link [LNKA] ->
GSI 10 (level, low) -> IRQ 10
[   78.874845] sata_sil 0000:00:0d.0: Applying R_ERR on DMA activate
FIS errata fix
[   78.876328] ata3: SATA max UDMA/100 cmd 0xE080E480 ctl 0xE080E48A
bmdma 0xE080E400 irq 10
[   78.877438] ata4: SATA max UDMA/100 cmd 0xE080E4C0 ctl 0xE080E4CA
bmdma 0xE080E408 irq 10
[   78.878493] ata5: SATA max UDMA/100 cmd 0xE080E680 ctl 0xE080E68A
bmdma 0xE080E600 irq 10
[   78.879554] ata6: SATA max UDMA/100 cmd 0xE080E6C0 ctl 0xE080E6CA
bmdma 0xE080E608 irq 10
[   79.249539] ata3: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
[   79.250836] ata3.00: cfg 49:2f00 82:7c6b 83:7f09 84:4003 85:7c69
86:3e01 87:4003 88:207f
[   79.250916] ata3.00: ATA-7, max UDMA/133, 585940320 sectors: LBA48
[   79.251092] ata3.00: applying bridge limits
[   79.252719] ata3.00: configured for UDMA/100
[   79.252881] scsi2 : sata_sil
[   79.619232] ata4: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
[   79.620859] ata4.00: cfg 49:2f00 82:346b 83:7d01 84:4023 85:3469
86:3c01 87:4023 88:203f
[   79.620936] ata4.00: ATA-7, max UDMA/100, 781422768 sectors: LBA48
[   79.621108] ata4.00: applying bridge limits
[   79.623020] ata4.00: configured for UDMA/100
[   79.623185] scsi3 : sata_sil
[   79.988934] ata5: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
[   79.990275] ata5.00: cfg 49:2f00 82:346b 83:7f01 84:4003 85:3469
86:3e01 87:4003 88:203f
[   79.990350] ata5.00: ATA-6, max UDMA/100, 625142448 sectors: LBA48
[   79.990528] ata5.00: applying bridge limits
[   79.992177] ata5.00: configured for UDMA/100
[   79.992336] scsi4 : sata_sil
[   80.198745] ata6: SATA link down (SStatus 0 SControl 310)
[   80.198948] scsi5 : sata_sil
[   80.204337]   Vendor: ATA       Model: Maxtor 4A300J0    Rev: RAMB
[   80.206515]   Type:   Direct-Access                      ANSI SCSI
revision: 05
[   80.214517]   Vendor: ATA       Model: ST3400832A        Rev: 3.01
[   80.216702]   Type:   Direct-Access                      ANSI SCSI
revision: 05
[   80.224985]   Vendor: ATA       Model: WDC WD3200JB-00K  Rev: 08.0
[   80.227156]   Type:   Direct-Access                      ANSI SCSI
revision: 05
[   80.237964] SCSI device sda: 490234752 512-byte hdwr sectors (251000 MB)
[   80.238870] sda: Write Protect is off
[   80.239039] sda: Mode Sense: 00 3a 00 00
[   80.240146] SCSI device sda: drive cache: write back
[   80.243111] SCSI device sda: 490234752 512-byte hdwr sectors (251000 MB)
[   80.243940] sda: Write Protect is off
[   80.244099] sda: Mode Sense: 00 3a 00 00
[   80.245426] SCSI device sda: drive cache: write back
[   80.245611]  sda: unknown partition table
[   80.256731] sd 0:0:0:0: Attached scsi disk sda
[   80.260179] SCSI device sdb: 625142448 512-byte hdwr sectors (320073 MB)
[   80.260912] sdb: Write Protect is off
[   80.261069] sdb: Mode Sense: 00 3a 00 00
[   80.262194] SCSI device sdb: drive cache: write back
[   80.265003] SCSI device sdb: 625142448 512-byte hdwr sectors (320073 MB)
[   80.265826] sdb: Write Protect is off
[   80.265982] sdb: Mode Sense: 00 3a 00 00
[   80.267291] SCSI device sdb: drive cache: write back
[   80.267472]  sdb: unknown partition table
[   80.285352] sd 1:0:0:0: Attached scsi disk sdb
[   80.288855] SCSI device sdc: 585940320 512-byte hdwr sectors (300001 MB)
[   80.289591] sdc: Write Protect is off
[   80.289746] sdc: Mode Sense: 00 3a 00 00
[   80.290850] SCSI device sdc: drive cache: write back
[   80.293698] SCSI device sdc: 585940320 512-byte hdwr sectors (300001 MB)
[   80.294522] sdc: Write Protect is off
[   80.294690] sdc: Mode Sense: 00 3a 00 00
[   80.296010] SCSI device sdc: drive cache: write back
[   80.296195]  sdc: sdc1
[   80.311462] sd 2:0:0:0: Attached scsi disk sdc
[   80.314639] SCSI device sdd: 781422768 512-byte hdwr sectors (400088 MB)
[   80.315380] sdd: Write Protect is off
[   80.315543] sdd: Mode Sense: 00 3a 00 00
[   80.316657] SCSI device sdd: drive cache: write back
[   80.319566] SCSI device sdd: 781422768 512-byte hdwr sectors (400088 MB)
[   80.320398] sdd: Write Protect is off
[   80.320550] sdd: Mode Sense: 00 3a 00 00
[   80.321844] SCSI device sdd: drive cache: write back
[   80.322036]  sdd: unknown partition table
[   80.349634] sd 3:0:0:0: Attached scsi disk sdd
[   80.352706] SCSI device sde: 625142448 512-byte hdwr sectors (320073 MB)
[   80.353444] sde: Write Protect is off
[   80.353597] sde: Mode Sense: 00 3a 00 00
[   80.354702] SCSI device sde: drive cache: write back
[   80.357583] SCSI device sde: 625142448 512-byte hdwr sectors (320073 MB)
[   80.358587] sde: Write Protect is off
[   80.358751] sde: Mode Sense: 00 3a 00 00
[   80.360080] SCSI device sde: drive cache: write back
[   80.360264]  sde: sde1 sde2
[   80.385363] sd 4:0:0:0: Attached scsi disk sde
[   80.389764] PNP: PS/2 Controller [PNP0303:PS2K,PNP0f03:PS2M] at
0x60,0x64 irq 1,12
[   80.394116] serio: i8042 AUX port at 0x60,0x64 irq 12
[   80.394449] serio: i8042 KBD port at 0x60,0x64 irq 1
[   80.406094] mice: PS/2 mouse device common for all mice
[   80.407876] NET: Registered protocol family 1
[   80.408210] Using IPI Shortcut mode
[   80.408443] Time: tsc clocksource has been installed.
[   80.412694] ACPI: (supports S0 S1 S4 S5)
[   80.415370] Freeing unused kernel memory: 164k freed
[   80.416526] Write protecting the kernel read-only data: 315k
[   80.487193] ReiserFS: sdc1: found reiserfs format "3.6" with standard journal
[   80.537005] input: AT Translated Set 2 keyboard as /class/input/input0
[   80.736743] logips2pp: Detected unknown logitech mouse model 0
[   81.273027] input: PS/2 Logitech Mouse as /class/input/input1
[   99.653150] ReiserFS: sdc1: using ordered data mode
[   99.686429] ReiserFS: sdc1: journal params: device sdc1, size 8192,
journal first block 18, max trans len 1024, max batch 900, max commit
age 30, max trans age 30
[   99.691304] ReiserFS: sdc1: checking transaction log (sdc1)
[   99.797532] ReiserFS: sdc1: Using r5 hash to sort names
[  110.888668] Real Time Clock Driver v1.12ac
[  114.404370] Linux Tulip driver version 1.1.13-NAPI (December 15, 2004)
[  114.413359] ACPI: PCI Interrupt Link [LNKC] enabled at IRQ 9
[  114.413559] PCI: setting IRQ 9 as level-triggered
[  114.413611] ACPI: PCI Interrupt 0000:00:0b.0[A] -> Link [LNKC] ->
GSI 9 (level, low) -> IRQ 9
[  114.447805] tulip0:  EEPROM default media type Autosense.
[  114.447986] tulip0:  Index #0 - Media MII (#11) described by a
21142 MII PHY (3) block.
[  114.454699] tulip0:  MII transceiver #1 config 1000 status 782d
advertising 01e1.
[  114.470799] eth0: Digital DS21143 Tulip rev 65 at 0001d000,
00:C0:F0:4A:0C:46, IRQ 9.
[  114.542173] pcnet32.c:v1.32 18.Mar.2006 tsbogend@alpha.franken.de
[  114.680479] NET: Registered protocol family 5
[  114.888557] ns83820.c: National Semiconductor DP83820 10/100/1000 driver.
[  114.892246] ACPI: PCI Interrupt 0000:00:09.0[A] -> Link [LNKA] ->
GSI 10 (level, low) -> IRQ 10
[  114.892872] eth1: ns83820.c: 0x22c: 00000000, subsystem: 0000:0000
[  114.920733] eth1: ns83820 v0.23: DP83820 v1.2: 00:4f:4a:00:13:5a
io=0xefffb000 irq=10 f=sg
[  116.447861] Loading Reiser4. See www.namesys.com for a description
of Reiser4.
[  156.772409] JFS: nTxBlock = 3923, nTxLock = 31389
[  177.328211] Installing knfsd (copyright (C) 1996 okir@monad.swb.de).
[  181.900651] eth1: link now 1000 mbps, full duplex and up.
[  184.486739] 0000:00:0b.0: tulip_stop_rxtx() failed (CSR5 0xf0660000
CSR6 0xb20e2202)
[  184.486819] eth0: Setting full-duplex based on MII#1 link partner
capability of cde1.
[  206.152537] NFSD: Using /var/lib/nfs/v4recovery as the NFSv4 state
recovery directory
[  206.160050] NFSD: starting 90-second grace period
[  418.772720] (            smbd-932  |#0): new 342307229 us user-latency.
[  418.772909] stopped custom tracer.
[  418.773058]
[  418.773072] ======================================
[  418.773345] [ BUG: bad unlock ordering detected! ]
[  418.773505] --------------------------------------
[  418.773667] smbd/932 is trying to release lock (&mgr->tmgr_lock) at:
[  418.773964]  [<e09a7c3e>] try_capture+0x309/0x9b6 [reiser4]
[  418.774349] but the next lock to release is:
[  418.774503]  (&atom->alock){--..}, at: [<e09a7c02>]
try_capture+0x2cd/0x9b6 [reiser4]
[  418.775040]
[  418.775054] other info that might help us debug this:
[  418.775326] 3 locks held by smbd/932:
[  418.775480]  #0:  (&inode->i_mutex){--..}, at: [<c0299d58>]
mutex_lock+0xd/0xf
[  418.776037]  #1:  (&mgr->tmgr_lock){--..}, at: [<e09a7ad5>]
try_capture+0x1a0/0x9b6 [reiser4]
[  418.776643]  #2:  (&txnh->hlock){--..}, at: [<e09a7add>]
try_capture+0x1a8/0x9b6 [reiser4]
[  418.777261]
[  418.777275] stack backtrace:
[  418.779285]  [<c01032ab>] show_trace_log_lvl+0x64/0x125
[  418.779723]  [<c01038bd>] show_trace+0x1b/0x20
[  418.780133]  [<c0103914>] dump_stack+0x1f/0x24
[  418.780545]  [<c012f4b9>] lockdep_release+0x192/0x35e
[  418.782293]  [<c029b6dc>] _spin_unlock+0x19/0x27
[  418.784047]  [<e09a7c3e>] try_capture+0x309/0x9b6 [reiser4]
[  418.784832]  [<e09a214d>] longterm_lock_znode+0x2fc/0x415 [reiser4]
[  418.785337]  [<e09af864>] coord_by_handle+0x142/0xb76 [reiser4]
[  418.786144]  [<e09b03ac>] coord_by_key+0x55/0x5a [reiser4]
[  418.786920]  [<e09a3ca5>] insert_by_key+0x31/0x5c [reiser4]
[  418.787443]  [<e09bb75d>] write_sd_by_inode_common+0x117/0x502 [reiser4]
[  418.788644]  [<e09bbb75>] create_object_common+0x2d/0x37 [reiser4]
[  418.789774]  [<e09b8f37>] create_vfs_object+0x376/0x551 [reiser4]
[  418.790870]  [<e09b919b>] create_common+0x44/0x4b [reiser4]
[  418.791979]  [<c0167a6e>] vfs_create+0x67/0xad
[  418.795287]  [<c016a832>] open_namei+0x19b/0x6cd
[  418.798452]  [<c0158d64>] do_filp_open+0x2b/0x42
[  418.800948]  [<c0158ddc>] do_sys_open+0x61/0xef
[  418.803640]  [<c0158e9d>] sys_open+0x18/0x1a
[  418.806315]  [<c029b8cc>] syscall_call+0x7/0xb

Re: 2.6.17-rc5-mm3: bad unlock ordering (reiser4?)

[Andrew Morton]

On Sun, 4 Jun 2006 05:04:29 -0700
"Barry K. Nathan" <barryn@pobox.com> wrote:

> [ 1637.890434]
> [ 1637.890440] ======================================
> [ 1637.890641] [ BUG: bad unlock ordering detected! ]
> [ 1637.890741] --------------------------------------
> [ 1637.890841] mv/935 is trying to release lock (&mgr->tmgr_lock) at:
> [ 1637.890996]  [<e098e01b>] try_capture+0x306/0x9b1 [reiser4]
> [ 1637.891255] but the next lock to release is:
> [ 1637.891344]  (&atom->alock){--..}, at: [<e098dfe2>]
> try_capture+0x2cd/0x9b1 [reiser4]
> [ 1637.891667]
> [ 1637.891670] other info that might help us debug this:
> [ 1637.891854] 3 locks held by mv/935:
> [ 1637.891951]  #0:  (&inode->i_mutex/1){--..}, at: [<c0160325>]
> lock_rename+0xba/0xc1
> [ 1637.892297]  #1:  (&mgr->tmgr_lock){--..}, at: [<e098deb5>]
> try_capture+0x1a0/0x9b1 [reiser4]
> [ 1637.892647]  #2:  (&txnh->hlock){--..}, at: [<e098debd>]
> try_capture+0x1a8/0x9b1 [reiser4]
> [ 1637.892994]
> [ 1637.892996] stack backtrace:
> [ 1637.893577]  [<c010311a>] show_trace_log_lvl+0x54/0xfd
> [ 1637.893738]  [<c0103709>] show_trace+0xd/0x10
> [ 1637.893893]  [<c0103750>] dump_stack+0x19/0x1b
> [ 1637.894045]  [<c012d713>] lockdep_release+0x18b/0x350
> [ 1637.894407]  [<c02880d9>] _spin_unlock+0x16/0x1f
> [ 1637.894777]  [<e098e01b>] try_capture+0x306/0x9b1 [reiser4]
> [ 1637.895048]  [<e0988a80>] longterm_lock_znode+0x2e3/0x3e3 [reiser4]
> [ 1637.895254]  [<e0995790>] coord_by_handle+0x136/0xaf4 [reiser4]
> [ 1637.895515]  [<e09962de>] object_lookup+0x8e/0x96 [reiser4]
> [ 1637.895764]  [<e09a9ece>] find_entry+0xbb/0x200 [reiser4]
> [ 1637.896134]  [<e099fab1>] rename_common+0x96b/0x9b6 [reiser4]
> [ 1637.896440]  [<c0160e96>] vfs_rename+0x1dd/0x315
> [ 1637.897098]  [<c0162b84>] sys_renameat+0x1bb/0x22a
> [ 1637.897664]  [<c0162c05>] sys_rename+0x12/0x14
> [ 1637.898220]  [<c0288283>] syscall_call+0x7/0xb

Why does the locking validator complain about unlocking ordering?

Re: 2.6.17-rc5-mm3: bad unlock ordering (reiser4?)

[Valdis.Kletnieks]

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

On Sun, 04 Jun 2006 13:33:26 PDT, Andrew Morton said:

> Why does the locking validator complain about unlocking ordering?

Presumably, if the lock nesting *should* be "take A, take B, release B,
release A", if it sees "Take A, Take B, release A" it means there's
potentially a missing 'release B' that got forgotten (most likely an
error case that does a 'return;' instead of a 'goto end_of_function_cleanup'
like we usually code.

Having said that, I'm not sure it qualifies as a "BUG".  Certainly would
qualify for a "SMELLS_FISHY" though.  But we don't have one of those handy,
so maybe BUG is as good as it gets (given that the person who built the
kernel *asked* to be nagged about locking funkyness)....

[-- Attachment #2: Type: application/pgp-signature, Size: 226 bytes --]

Re: 2.6.17-rc5-mm3: bad unlock ordering (reiser4?)

[Ingo Molnar]

* Valdis.Kletnieks@vt.edu <Valdis.Kletnieks@vt.edu> wrote:

> On Sun, 04 Jun 2006 13:33:26 PDT, Andrew Morton said:
> 
> > Why does the locking validator complain about unlocking ordering?
> 
> Presumably, if the lock nesting *should* be "take A, take B, release 
> B, release A", if it sees "Take A, Take B, release A" it means there's 
> potentially a missing 'release B' that got forgotten (most likely an 
> error case that does a 'return;' instead of a 'goto 
> end_of_function_cleanup' like we usually code.
> 
> Having said that, I'm not sure it qualifies as a "BUG".  Certainly 
> would qualify for a "SMELLS_FISHY" though.  But we don't have one of 
> those handy, so maybe BUG is as good as it gets (given that the person 
> who built the kernel *asked* to be nagged about locking funkyness)....

yes. This warning caught a couple of bugs, and documented a couple of 
'fishy' places. Sometimes it's code that is totally correct. I think 
it's worth the extra iteration, there arent that many non-nested 
unlocking places.

straight nested unlocking is also best for performance and scalability: 
the outmost lock should be released last, because that's what the 
waiters are most likely to be blocking/spinning upon.

nevertheless i'll turn that warning into a less scary message.

	Ingo

Re: 2.6.17-rc5-mm3: bad unlock ordering (reiser4?)

[Barry K. Nathan]

On 6/4/06, Ingo Molnar <mingo@elte.hu> wrote:
> nevertheless i'll turn that warning into a less scary message.

This discussion seems to imply that I reported a false positive... is
it *known* that I reported a false positive, or is it only a strong
possibility?

Assuming it's a false positive: Since this stops the tracer, it means
that if an actual deadlock possibility is detected later [I'm assuming
that detection of those doesn't get shut down by the bad-lock-ordering
detection either], useful information could be missing from
/proc/latency_trace, if I am not mistaken. Perhaps this could impede
lockdep testing for people running reiser4 filesystems. I guess this
is just a theoretical possibility at this point, but perhaps it's
worth mentioning.
-- 
-Barry K. Nathan <barryn@pobox.com>

Re: 2.6.17-rc5-mm3: bad unlock ordering (reiser4?)

[Hans Reiser]

Barry K. Nathan wrote:

> On 6/4/06, Ingo Molnar <mingo@elte.hu> wrote:
>
>> nevertheless i'll turn that warning into a less scary message.
>
>
> This discussion seems to imply that I reported a false positive... is
> it *known* that I reported a false positive, or is it only a strong
> possibility?
>
> Assuming it's a false positive: Since this stops the tracer, it means
> that if an actual deadlock possibility is detected later [I'm assuming
> that detection of those doesn't get shut down by the bad-lock-ordering
> detection either], useful information could be missing from
> /proc/latency_trace, if I am not mistaken. Perhaps this could impede
> lockdep testing for people running reiser4 filesystems. I guess this
> is just a theoretical possibility at this point, but perhaps it's
> worth mentioning.

Monday Russian time Zam will be in, he is the locking guy for reiser4.

Re: 2.6.17-rc5-mm3: bad unlock ordering (reiser4?)

[Ingo Molnar]

* Barry K. Nathan <barryn@pobox.com> wrote:

> Assuming it's a false positive: Since this stops the tracer, it means 
> that if an actual deadlock possibility is detected later [I'm assuming 
> that detection of those doesn't get shut down by the bad-lock-ordering 
> detection either], useful information could be missing from 
> /proc/latency_trace, [...]

reporting the first one only is necessary, because the validator cannot 
trust a system's dependency info that it sees as incorrect. Deadlock 
possibilities are quite rare in a kernel that is "in balance". Right now 
we are not "in balance" yet, because the validator has only been added a 
couple of days ago. The flurry of initial fixes will die down quickly.

you can fix the reiser4 false positive (it's likely a false positive) by 
changing the spin_unlock() to spin_unlock_non_nested(). The patch below 
should do that for this specific instance.

Ob'Reiser4'Cleanup:

	spin_unlock(&(mgr->tmgr_lock));

why isnt that:

	spin_unlock(&mgr->tmgr_lock);

? fs/reiser4/*.c is infested with that, the string '(&(' occurs 199 (!) 
times.

also:

        if (atomic_read(&node->d_count) != 0) {
                return 0;
        }

why the braces, when on the next line it's not done:

        if (blocknr_is_fake(jnode_get_block(node)))
                return 0;

it looks quite inconsistent. Also, just a quick look at just about any 
file in reiser4/*.c shows alot of other coding style inconsistencies.

	Ingo

Index: linux/fs/reiser4/txnmgr.h
===================================================================
--- linux.orig/fs/reiser4/txnmgr.h
+++ linux/fs/reiser4/txnmgr.h
@@ -613,7 +613,7 @@ static inline void spin_unlock_txnmgr(tx
 	LOCK_CNT_DEC(spin_locked_txnmgr);
 	LOCK_CNT_DEC(spin_locked);
 
-	spin_unlock(&(mgr->tmgr_lock));
+	spin_unlock_non_nested(&(mgr->tmgr_lock));
 }
 
 typedef enum {

Re: 2.6.17-rc5-mm3: bad unlock ordering (reiser4?)

[Ingo Molnar]

* Ingo Molnar <mingo@elte.hu> wrote:

> +++ linux/fs/reiser4/txnmgr.h
> @@ -613,7 +613,7 @@ static inline void spin_unlock_txnmgr(tx
>  	LOCK_CNT_DEC(spin_locked_txnmgr);
>  	LOCK_CNT_DEC(spin_locked);
>  
> -	spin_unlock(&(mgr->tmgr_lock));
> +	spin_unlock_non_nested(&(mgr->tmgr_lock));
>  }
>  
>  typedef enum {

Btw., this particular annotation also documents a locking/scalability 
inefficiency. mgr->tmgr_lock is a "global" lock (per superblock it 
seems), while atom->alock is a more "finegrained" lock.

Typical usage: tmgr_lock is used a 'master lock', it's taken, then 
atom->alock is taken, and then ->tmgr_lock is released. Then code runs 
under atom->alock, and atom->alock is released finally.

The scalability problem with such 'master locks' is that they pretty 
much control scalability, so the scalability advantage of the finer 
grained lock is reduced (often eliminated). Since access to the finer 
grained lock goes via the master lock, the master lock cacheline will 
bounce from CPU to CPU.

A much more scalable design is to get to the finer grained lock in some 
read-mostly, lockless way, and then take it. This often necessiates the 
utilization of RCU, but it's well worth it.

There's other kernel code that has been annotated for similar reasons - 
e.g. the netfilter code makes frequent use of master-locks.

All in one, it's a good idea to document such locking constructs via the 
_non_nested() annotation. Often they can be eliminated altogether and 
the code improves. It's not a maintainance problem either, because right 
now there are only 42 such annotations, out of 46,000+ locking API uses 
covered by the lock validator.

	Ingo

Re: 2.6.17-rc5-mm3: bad unlock ordering (reiser4?)

[Alexander Zarochentsev]

Hello,

On Monday 05 June 2006 11:37, Ingo Molnar wrote:
> * Ingo Molnar <mingo@elte.hu> wrote:
> > +++ linux/fs/reiser4/txnmgr.h
> > @@ -613,7 +613,7 @@ static inline void spin_unlock_txnmgr(tx
> >  	LOCK_CNT_DEC(spin_locked_txnmgr);
> >  	LOCK_CNT_DEC(spin_locked);
> >
> > -	spin_unlock(&(mgr->tmgr_lock));
> > +	spin_unlock_non_nested(&(mgr->tmgr_lock));
> >  }
> >
> >  typedef enum {
>
> Btw., this particular annotation also documents a locking/scalability
> inefficiency. mgr->tmgr_lock is a "global" lock (per superblock it
> seems), while atom->alock is a more "finegrained" lock.
>
> Typical usage: tmgr_lock is used a 'master lock', it's taken, then
> atom->alock is taken, and then ->tmgr_lock is released. Then code
> runs under atom->alock, and atom->alock is released finally.

> The scalability problem with such 'master locks' is that they pretty
> much control scalability, so the scalability advantage of the finer
> grained lock is reduced (often eliminated). Since access to the finer
> grained lock goes via the master lock, the master lock cacheline will
> bounce from CPU to CPU.

please note that the master lock is taken by try_caputure only if new 
atom is created.  It is likely than current thread has an atom already 
or the block already captured.

> A much more scalable design is to get to the finer grained lock in
> some read-mostly, lockless way, and then take it. This often
> necessiates the utilization of RCU, but it's well worth it.

There was a code to measure lock contention for reiser4 locks which 
showed that the tmgr lock was contented less than atom and jnode spin 
locks were. 

> There's other kernel code that has been annotated for similar reasons
> - e.g. the netfilter code makes frequent use of master-locks.

> All in one, it's a good idea to document such locking constructs via
> the _non_nested() annotation. Often they can be eliminated altogether
> and the code improves. It's not a maintainance problem either,
> because right now there are only 42 such annotations, out of 46,000+
> locking API uses covered by the lock validator.

I think the txnh lock and the tmgr lock are _non_nested.  And, there is  
a place where two atom locks are taken in deadlock-free order w/o 
always keeping correct order of unlocking.  The latest thing can be 
made lock-validator-friendly.

> 	Ingo

Best,
Alex.

Re: 2.6.17-rc5-mm3: bad unlock ordering (reiser4?)

[Ingo Molnar]

* Alexander Zarochentsev <zam@namesys.com> wrote:

> I think the txnh lock and the tmgr lock are _non_nested. [...]

ok - that's what the two changes i did do.

> [...]  And, there is a place where two atom locks are taken in 
> deadlock-free order w/o always keeping correct order of unlocking.  
> The latest thing can be made lock-validator-friendly.

could you send a patch for that? When there is single-depth nesting of 
two atom-locks then the annotation is easy, instead of:

	spin_lock(&atom->alock);

you should do:

	spin_lock_nested(&atom->alock, SINGLE_DEPTH_NESTING)

for the unordered unlocks, just change the one that is non-nested to 
spin_unlock_non_nested(). (the second lock can stay spin_unlock() - that 
will be in order again)

	Ingo

Re: 2.6.17-rc5-mm3: bad unlock ordering (reiser4?)

[Hans Reiser]

I just want to thank Ingo for designing this tool.  While it did not
find a reiser4 bug today, probably some day it will.  I hope we as a
kernel community can make automated code inspection/monitoring more and
more sophisticated over the next few years, and this is a nice little
step down that path.

Hans

Re: 2.6.17-rc5-mm3: bad unlock ordering (reiser4?)

[Barry K. Nathan]

On 6/4/06, Ingo Molnar <mingo@elte.hu> wrote:
> reporting the first one only is necessary, because the validator cannot
> trust a system's dependency info that it sees as incorrect. Deadlock
> possibilities are quite rare in a kernel that is "in balance". Right now
> we are not "in balance" yet, because the validator has only been added a
> couple of days ago. The flurry of initial fixes will die down quickly.

So, does that mean the plan is to annotate/tweak things in order to
shut up *each and every* false positive in the kernel?

Anyway, I tried your patch and I got this:

[  401.004071] (            smbd-920  |#0): new 324990707 us user-latency.
[  401.004264] stopped custom tracer.
[  401.004412]
[  401.004425] ======================================
[  401.004687] [ BUG: bad unlock ordering detected! ]
[  401.004849] --------------------------------------
[  401.005010] smbd/920 is trying to release lock (&txnh->hlock) at:
[  401.005302]  [<e09a8332>] get_current_atom_locked_nocheck+0x3d/0x46 [reiser4]
[  401.005702] but the next lock to release is:
[  401.005856]  (&atom->alock){--..}, at: [<e09a78da>]
txnh_get_atom+0x23/0x85 [reiser4]
[  401.006391]
[  401.006405] other info that might help us debug this:
[  401.006660] 2 locks held by smbd/920:
[  401.006804]  #0:  (&inode->i_mutex){--..}, at: [<c0299d58>]
mutex_lock+0xd/0xf
[  401.007373]  #1:  (&txnh->hlock){--..}, at: [<e09a78cc>]
txnh_get_atom+0x15/0x85 [reiser4]
[  401.008021]
[  401.008034] stack backtrace:
[  401.010115]  [<c01032ab>] show_trace_log_lvl+0x64/0x125
[  401.010538]  [<c01038bd>] show_trace+0x1b/0x20
[  401.010955]  [<c0103914>] dump_stack+0x1f/0x24
[  401.011367]  [<c012f4b9>] lockdep_release+0x192/0x35e
[  401.013039]  [<c029b6dc>] _spin_unlock+0x19/0x27
[  401.014899]  [<e09a8332>] get_current_atom_locked_nocheck+0x3d/0x46 [reiser4]
[  401.015674]  [<e09b3c83>] oid_count_allocated+0xd/0x2c [reiser4]
[  401.016649]  [<e09bb853>] write_sd_by_inode_common+0x1fd/0x502 [reiser4]
[  401.017788]  [<e09bbb85>] create_object_common+0x2d/0x37 [reiser4]
[  401.018926]  [<e09b8f47>] create_vfs_object+0x376/0x551 [reiser4]
[  401.020011]  [<e09b91ab>] create_common+0x44/0x4b [reiser4]
[  401.021047]  [<c0167a6e>] vfs_create+0x67/0xad
[  401.024271]  [<c016a832>] open_namei+0x19b/0x6cd
[  401.027492]  [<c0158d64>] do_filp_open+0x2b/0x42
[  401.030193]  [<c0158ddc>] do_sys_open+0x61/0xef
[  401.032721]  [<c0158e9d>] sys_open+0x18/0x1a
[  401.035432]  [<c029b8cc>] syscall_call+0x7/0xb

dmesg and /proc/latency_trace are here:
http://members.cox.net/barrykn/linux/trace/dmesg.reiser4-3
http://members.cox.net/barrykn/linux/trace/latency_trace_reiser4-3.bz2
-- 
-Barry K. Nathan <barryn@pobox.com>

Re: 2.6.17-rc5-mm3: bad unlock ordering (reiser4?)

[Ingo Molnar]

* Barry K. Nathan <barryn@pobox.com> wrote:

> On 6/4/06, Ingo Molnar <mingo@elte.hu> wrote:
> >reporting the first one only is necessary, because the validator cannot
> >trust a system's dependency info that it sees as incorrect. Deadlock
> >possibilities are quite rare in a kernel that is "in balance". Right now
> >we are not "in balance" yet, because the validator has only been added a
> >couple of days ago. The flurry of initial fixes will die down quickly.
> 
> So, does that mean the plan is to annotate/tweak things in order to 
> shut up *each and every* false positive in the kernel?

yes. Note that for the many reasons i outlined before they are only 
"half false positives" - i.e. they are potentially dangerous constructs 
and they are potentially inefficient - hence we _want to_ document them 
in the code, to increase the cleanliness of the kernel. A pure "false 
positive" would be a totally valid and perfect locking construct being 
flagged by the lock validator.

nor do these warnings really hurt anyone. Lockdep prints info and then 
shuts up - the system continues to work.

> Anyway, I tried your patch and I got this:

please try the addon patch below.

	Ingo

Index: linux/fs/reiser4/txnmgr.h
===================================================================
--- linux.orig/fs/reiser4/txnmgr.h
+++ linux/fs/reiser4/txnmgr.h
@@ -567,7 +567,7 @@ static inline void spin_unlock_txnh(txn_
 	LOCK_CNT_DEC(spin_locked_txnh);
 	LOCK_CNT_DEC(spin_locked);
 
-	spin_unlock(&(txnh->hlock));
+	spin_unlock_non_nested(&(txnh->hlock));
 }
 
 #define spin_ordering_pred_txnmgr(tmgr)		\

Re: 2.6.17-rc5-mm3: bad unlock ordering (reiser4?)

[Barry K. Nathan]

On 6/5/06, Ingo Molnar <mingo@elte.hu> wrote:
>
> * Barry K. Nathan <barryn@pobox.com> wrote:
[snip]
> > So, does that mean the plan is to annotate/tweak things in order to
> > shut up *each and every* false positive in the kernel?
>
> yes. Note that for the many reasons i outlined before they are only
> "half false positives" - i.e. they are potentially dangerous constructs
> and they are potentially inefficient - hence we _want to_ document them
> in the code, to increase the cleanliness of the kernel. A pure "false
> positive" would be a totally valid and perfect locking construct being
> flagged by the lock validator.
>
> nor do these warnings really hurt anyone. Lockdep prints info and then
> shuts up - the system continues to work.

Ok, thanks for explaining that.

> > Anyway, I tried your patch and I got this:
>
> please try the addon patch below.

I don't know if you saw this comment on the lock validator article at LWN?

---begin quote---
The kernel lock validator
Posted May 31, 2006 9:35 UTC (Wed) by subscriber nix [Link]

... and now reiser4 turns up with a tree of locks where each rank may
be taken within the rank above safely, but where there are a
potentially unbounded number of ranks...
---end quote---

I have no idea if that's actually the case, but if it is, it might be relevant.

Anyway, I have a new, more scary-looking lockdep warning:

http://members.cox.net/barrykn/linux/trace/dmesg.reiser4-4
http://members.cox.net/barrykn/linux/trace/latency_trace_reiser4-4.bz2

[  316.680616] (            smbd-824  |#0): new 239822061 us user-latency.
[  316.680805] stopped custom tracer.
[  316.680951]
[  316.680964] =====================================================
[  316.681241] [ BUG: possible circular locking deadlock detected! ]
[  316.681412] -----------------------------------------------------
[  316.681575] smbd/824 is trying to acquire lock:
[  316.681727]  (&txnh->hlock){--..}, at: [<e09a884a>]
txn_end+0x3f9/0x47c [reiser4]
[  316.682366]
[  316.682379] but task is already holding lock:
[  316.682629]  (&atom->alock){--..}, at: [<e09a78da>]
txnh_get_atom+0x23/0x85 [reiser4]
[  316.683192]
[  316.683206] which lock already depends on the new lock,
[  316.683472] which could lead to circular deadlocks!
[  316.683633]
[  316.683648] the existing dependency chain (in reverse order) is:
[  316.683922]
[  316.683936] -> #1 (&atom->alock){--..}:
[  316.684392]        [<c012f30f>] lockdep_acquire+0x67/0x7f
[  316.685084]        [<c029b67f>] _spin_lock+0x1d/0x2b
[  316.685772]        [<e09a7c0c>] try_capture+0x2d0/0x9cb [reiser4]
[  316.686514]        [<e09a214d>] longterm_lock_znode+0x2fc/0x415 [reiser4]
[  316.687245]        [<e09af884>] coord_by_handle+0x142/0xb76 [reiser4]
[  316.687982]        [<e09b03cc>] coord_by_key+0x55/0x5a [reiser4]
[  316.688714]        [<e09a3ca5>] insert_by_key+0x31/0x5c [reiser4]
[  316.689483]        [<e09bb77d>]
write_sd_by_inode_common+0x117/0x502 [reiser4]
[  316.690340]        [<e09bbb95>] create_object_common+0x2d/0x37 [reiser4]
[  316.691092]        [<e09b8f57>] create_vfs_object+0x376/0x551 [reiser4]
[  316.691841]        [<e09b91bb>] create_common+0x44/0x4b [reiser4]
[  316.692581]        [<c0167a6e>] vfs_create+0x67/0xad
[  316.693259]        [<c016a832>] open_namei+0x19b/0x6cd
[  316.693936]        [<c0158d64>] do_filp_open+0x2b/0x42
[  316.694621]        [<c0158ddc>] do_sys_open+0x61/0xef
[  316.695276]        [<c0158e9d>] sys_open+0x18/0x1a
[  316.695934]        [<c029b8cc>] syscall_call+0x7/0xb
[  316.696629]
[  316.696643] -> #0 (&txnh->hlock){--..}:
[  316.697087]        [<c012f30f>] lockdep_acquire+0x67/0x7f
[  316.697781]        [<c029b67f>] _spin_lock+0x1d/0x2b
[  316.698451]        [<e09a884a>] txn_end+0x3f9/0x47c [reiser4]
[  316.699242]        [<e09a443c>] reiser4_exit_context+0xb2/0x125 [reiser4]
[  316.699981]        [<e09b90f2>] create_vfs_object+0x511/0x551 [reiser4]
[  316.700729]        [<e09b91bb>] create_common+0x44/0x4b [reiser4]
[  316.701467]        [<c0167a6e>] vfs_create+0x67/0xad
[  316.702142]        [<c016a832>] open_namei+0x19b/0x6cd
[  316.702823]        [<c0158d64>] do_filp_open+0x2b/0x42
[  316.703493]        [<c0158ddc>] do_sys_open+0x61/0xef
[  316.704159]        [<c0158e9d>] sys_open+0x18/0x1a
[  316.704831]        [<c029b8cc>] syscall_call+0x7/0xb
[  316.705518]
[  316.705532] other info that might help us debug this:
[  316.705566]
[  316.705936] 2 locks held by smbd/824:
[  316.706085]  #0:  (&inode->i_mutex){--..}, at: [<c0299d58>]
mutex_lock+0xd/0xf
[  316.706654]  #1:  (&atom->alock){--..}, at: [<e09a78da>]
txnh_get_atom+0x23/0x85 [reiser4]
[  316.707335]
[  316.707349] stack backtrace:
[  316.709560]  [<c01032ab>] show_trace_log_lvl+0x64/0x125
[  316.710003]  [<c01038bd>] show_trace+0x1b/0x20
[  316.710421]  [<c0103914>] dump_stack+0x1f/0x24
[  316.710842]  [<c012e400>] print_circular_bug_tail+0x5d/0x69
[  316.712546]  [<c012eca2>] __lockdep_acquire+0x896/0xa91
[  316.714438]  [<c012f30f>] lockdep_acquire+0x67/0x7f
[  316.716133]  [<c029b67f>] _spin_lock+0x1d/0x2b
[  316.717929]  [<e09a884a>] txn_end+0x3f9/0x47c [reiser4]
[  316.718768]  [<e09a443c>] reiser4_exit_context+0xb2/0x125 [reiser4]
[  316.719319]  [<e09b90f2>] create_vfs_object+0x511/0x551 [reiser4]
[  316.720536]  [<e09b91bb>] create_common+0x44/0x4b [reiser4]
[  316.721610]  [<c0167a6e>] vfs_create+0x67/0xad
[  316.724954]  [<c016a832>] open_namei+0x19b/0x6cd
[  316.728125]  [<c0158d64>] do_filp_open+0x2b/0x42
[  316.730886]  [<c0158ddc>] do_sys_open+0x61/0xef
[  316.733473]  [<c0158e9d>] sys_open+0x18/0x1a
[  316.736245]  [<c029b8cc>] syscall_call+0x7/0xb

-- 
-Barry K. Nathan <barryn@pobox.com>

Re: 2.6.17-rc5-mm3: bad unlock ordering (reiser4?)

[Hans Reiser]

Ingo Molnar wrote:

>* Barry K. Nathan <barryn@pobox.com> wrote:
>
>  
>
>>On 6/4/06, Ingo Molnar <mingo@elte.hu> wrote:
>>    
>>
>>>reporting the first one only is necessary, because the validator cannot
>>>trust a system's dependency info that it sees as incorrect. Deadlock
>>>possibilities are quite rare in a kernel that is "in balance". Right now
>>>we are not "in balance" yet, because the validator has only been added a
>>>couple of days ago. The flurry of initial fixes will die down quickly.
>>>      
>>>
>>So, does that mean the plan is to annotate/tweak things in order to 
>>shut up *each and every* false positive in the kernel?
>>    
>>
>
>yes. 
>
Ingo is very much in the right here.  Things like locking are very hard
to debug, and require serious methodology.  It is worth the hassle.  I
hope we do more things like this in the future.

Re: 2.6.17-rc5-mm3: bad unlock ordering (reiser4?)

[Hans Reiser]

Ingo Molnar wrote:

>        if (atomic_read(&node->d_count) != 0) {
>                return 0;
>        }
>
>why the braces, when on the next line it's not done:
>
>        if (blocknr_is_fake(jnode_get_block(node)))
>                return 0;
>
>it looks quite inconsistent.
>
I have a (roughly adhered to) rule that I don't hassle programmers much
about the style of any code that I can easily read.  I truly do not care
where the braces are, I care if the comments and variable names are well
done.  So that is why, and yes, I know I am an unusual manager on this
point.