From: Sage Weil on
Hi,

I started seeing a hang during bootup of a machine with a umem
(micromemory nvram) card. I bisected it and narrowed it down to commit
b95a5680 which merged a couple nfsd changes, although strangely reverting
just b160fdab ('nfsd: nfsd_setattr needs to call commit_metadata') is
sufficient to make the problem go away.

I'm not quite sure what to make of it. I don't see how the nfsd change
would affect the umem driver initialization. The machine _is_ netbooting
(kernel via PXE, nfs root), though.

When it hangs, I see

[ 1.069553] v2.3 : Micro Memory(tm) PCI memory board block driver
[ 1.075780] umem 0000:02:01.0: can't find IRQ for PCI INT C; probably buggy MP table
[ 1.083633] umem 0000:02:01.0: Micro Memory(tm) controller found (PCI Mem Module (Battery Backup))
[ 1.092762] umem 0000:02:01.0: CSR 0xfc9ffc00 -> 0xffffc90001466c00 (0x100)
[ 1.099880] umem 0000:02:01.0: Size 1048576 KB, Battery 1 Disabled (FAILURE), Battery 2 Disabled (FAILURE)
[ 1.109745] umem 0000:02:01.0: Window size 16777216 bytes, IRQ 9
[ 1.115842] umem 0000:02:01.0: memory NOT initialized. Consider over-writing whole device.
[ 1.125778] umema:
[ 240.886560] INFO: task swapper:1 blocked for more than 120 seconds.
[ 240.893186] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 240.901115] swapper D 0000000000000001 0 1 0 0x00000000
[ 240.908231] ffff8800f8da1b50 0000000000000046 ffff8800f8da1ac0 ffff8800f8da1fd8
[ 240.916027] ffff8800f8d80050 0000000000004000 0000000000004000 00000000001d2180
[ 240.923819] 00000000001d2180 ffff8800f8da1fd8 ffff8800f8da1fd8 00000000001d2180
[ 240.931611] Call Trace:
[ 240.934133] [<ffffffff8144f96d>] ? _raw_spin_unlock_irqrestore+0x4c/0x68
[ 240.941011] [<ffffffff812a99ab>] ? mm_unplug_device+0x47/0x50
[ 240.946929] [<ffffffff8144cb84>] io_schedule+0x38/0x4d
[ 240.952238] [<ffffffff810802d0>] sync_page+0x4c/0x50
[ 240.957370] [<ffffffff8144cf9b>] __wait_on_bit_lock+0x42/0x8b
[ 240.963288] [<ffffffff81080284>] ? sync_page+0x0/0x50
[ 240.968508] [<ffffffff81080270>] __lock_page+0x64/0x6b
[ 240.973821] [<ffffffff8104b500>] ? wake_bit_function+0x0/0x2a
[ 240.979741] [<ffffffff81080796>] do_read_cache_page+0xd3/0x135
[ 240.985745] [<ffffffff810da132>] ? blkdev_readpage+0x0/0x15
[ 240.991492] [<ffffffff81080834>] read_cache_page_async+0x17/0x19
[ 240.997671] [<ffffffff8108083f>] read_cache_page+0x9/0x13
[ 241.003244] [<ffffffff81102a7b>] read_dev_sector+0x2e/0x93
[ 241.008903] [<ffffffff8110397c>] ? adfspart_check_ICS+0x0/0x19c
[ 241.014997] [<ffffffff811039b6>] adfspart_check_ICS+0x3a/0x19c
[ 241.021001] [<ffffffff81432011>] ? kmemleak_alloc+0x5b/0xa2
[ 241.026748] [<ffffffff810ab6d9>] ? kmem_cache_alloc+0x14f/0x17d
[ 241.032842] [<ffffffff8110397c>] ? adfspart_check_ICS+0x0/0x19c
[ 241.038934] [<ffffffff81103778>] rescan_partitions+0x196/0x39a
[ 241.044940] [<ffffffff8121a24e>] ? disk_get_part+0x74/0xbc
[ 241.050600] [<ffffffff810da63a>] __blkdev_get+0x271/0x365
[ 241.056172] [<ffffffff81222b14>] ? kobject_put+0x47/0x4c
[ 241.061658] [<ffffffff810da739>] blkdev_get+0xb/0xd
[ 241.066708] [<ffffffff81103121>] register_disk+0xbd/0x11f
[ 241.072274] [<ffffffff8121a3be>] add_disk+0xb8/0x116
[ 241.077414] [<ffffffff8193abbf>] mm_init+0x126/0x19e
[ 241.082556] [<ffffffff8193aa99>] ? mm_init+0x0/0x19e
[ 241.087693] [<ffffffff810001f0>] do_one_initcall+0x5a/0x14f
[ 241.093440] [<ffffffff81914908>] kernel_init+0x148/0x1d2
[ 241.098925] [<ffffffff81003794>] kernel_thread_helper+0x4/0x10
[ 241.104933] [<ffffffff8102cd00>] ? can_nice+0x19/0x3a
[ 241.110157] [<ffffffff8144fcc0>] ? restore_args+0x0/0x30
[ 241.115644] [<ffffffff819147c0>] ? kernel_init+0x0/0x1d2
[ 241.121128] [<ffffffff81003790>] ? kernel_thread_helper+0x0/0x10
[ 241.127300] 1 lock held by swapper/1:
[ 241.131046] #0: (&bdev->bd_mutex){+.+.+.}, at: [<ffffffff810da428>] __blkdev_get+0x5f/0x365

and with the above commit reverted, I get a 'normal' umem driver init (the
umem errors/warnings are normal.. the batteries aren't connected and the
card isn't being used):

Jun 17 12:49:58 ceph3 kernel: [ 2.270121] v2.3 : Micro Memory(tm) PCI memory board block driver
Jun 17 12:49:58 ceph3 kernel: [ 2.276360] umem 0000:02:01.0: PCI INT A -> GSI 20 (level, low) -> IRQ 20
Jun 17 12:49:58 ceph3 kernel: [ 2.283237] umem 0000:02:01.0: Micro Memory(tm) controller found (PCI Mem Module (Battery Backup))
Jun 17 12:49:58 ceph3 kernel: [ 2.292366] umem 0000:02:01.0: CSR 0xfc9ffc00 -> 0xffffc90001478c00 (0x100)
Jun 17 12:49:58 ceph3 kernel: [ 2.299476] umem 0000:02:01.0: Size 1048576 KB, Battery 1 Disabled (FAILURE), Battery 2 Disabled (FAILURE)
Jun 17 12:49:58 ceph3 kernel: [ 2.309507] umem 0000:02:01.0: Window size 16777216 bytes, IRQ 20
Jun 17 12:49:58 ceph3 kernel: [ 2.315691] umem 0000:02:01.0: memory NOT initialized. Consider over-writing whole device.
Jun 17 12:49:58 ceph3 kernel: [ 2.325697] umema:
Jun 17 12:49:58 ceph3 kernel: [ 2.328102] umem 0000:02:01.0: DMAstat - ANY_ERR MBE_ERR CHAIN_COMPLETE DMA_COMPLETE
Jun 17 12:49:58 ceph3 kernel: [ 2.328239] umem 0000:02:01.0: Memory access error detected (err count 0)
Jun 17 12:49:58 ceph3 kernel: [ 2.328239] umem 0000:02:01.0: Multi-bit EDC error
Jun 17 12:49:58 ceph3 kernel: [ 2.328239] umem 0000:02:01.0: Fault Address 0x0000000ff8, Fault Data 0xfff7fffdffffffff
Jun 17 12:49:58 ceph3 kernel: [ 2.328239] umem 0000:02:01.0: Fault Check 0x00, Fault Syndrome 0x00
Jun 17 12:49:58 ceph3 kernel: [ 2.354756] umem 0000:02:01.0: I/O error on sector 0/4096
Jun 17 12:49:58 ceph3 kernel: [ 2.360235] umem 0000:02:01.0: DMAstat - ANY_ERR MBE_ERR CHAIN_COMPLETE DMA_COMPLETE
Jun 17 12:49:58 ceph3 kernel: [ 2.360248] Buffer I/O error on device umema, logical block 0
Jun 17 12:49:58 ceph3 kernel: [ 2.366169] umem 0000:02:01.0: DMAstat - ANY_ERR MBE_ERR CHAIN_COMPLETE DMA_COMPLETE
Jun 17 12:49:58 ceph3 kernel: [ 2.366175] umem 0000:02:01.0: Memory access error detected (err count 0)
Jun 17 12:49:58 ceph3 kernel: [ 2.370075] umem 0000:02:01.0: Multi-bit EDC error
Jun 17 12:49:58 ceph3 kernel: [ 2.370075] umem 0000:02:01.0: Fault Address 0x0000000ff8, Fault Data 0xfff7fffdffffffff
Jun 17 12:49:58 ceph3 kernel: [ 2.370075] umem 0000:02:01.0: Fault Check 0x00, Fault Syndrome 0x00
Jun 17 12:49:58 ceph3 kernel: [ 2.392548] umem 0000:02:01.0: I/O error on sector 0/4096
Jun 17 12:49:58 ceph3 kernel: [ 2.398022] umem 0000:02:01.0: DMAstat - ANY_ERR MBE_ERR CHAIN_COMPLETE DMA_COMPLETE
Jun 17 12:49:58 ceph3 kernel: [ 2.398031] Buffer I/O error on device umema, logical block 0
Jun 17 12:49:58 ceph3 kernel: [ 2.403926] umem 0000:02:01.0: DMAstat - ANY_ERR MBE_ERR CHAIN_COMPLETE DMA_COMPLETE
Jun 17 12:49:58 ceph3 kernel: [ 2.403933] umem 0000:02:01.0: Memory access error detected (err count 0)
Jun 17 12:49:58 ceph3 kernel: [ 2.407853] umem 0000:02:01.0: Multi-bit EDC error
Jun 17 12:49:58 ceph3 kernel: [ 2.407853] umem 0000:02:01.0: Fault Address 0x0000000ff8, Fault Data 0xfff7fffdffffffff
Jun 17 12:49:58 ceph3 kernel: [ 2.407853] umem 0000:02:01.0: Fault Check 0x00, Fault Syndrome 0x00
Jun 17 12:49:58 ceph3 kernel: [ 2.430297] umem 0000:02:01.0: I/O error on sector 0/4096
Jun 17 12:49:58 ceph3 kernel: [ 2.435774] umem 0000:02:01.0: DMAstat - ANY_ERR MBE_ERR CHAIN_COMPLETE DMA_COMPLETE
Jun 17 12:49:58 ceph3 kernel: [ 2.435783] Buffer I/O error on device umema, logical block 0
Jun 17 12:49:58 ceph3 kernel: [ 2.441677] umem 0000:02:01.0: DMAstat - ANY_ERR MBE_ERR CHAIN_COMPLETE DMA_COMPLETE
Jun 17 12:49:58 ceph3 kernel: [ 2.441684] umem 0000:02:01.0: Memory access error detected (err count 0)
Jun 17 12:49:58 ceph3 kernel: [ 2.445605] umem 0000:02:01.0: Multi-bit EDC error
Jun 17 12:49:58 ceph3 kernel: [ 2.445605] umem 0000:02:01.0: Fault Address 0x0000000ff8, Fault Data 0xfff7fffdffffffff
Jun 17 12:49:58 ceph3 kernel: [ 2.445605] umem 0000:02:01.0: Fault Check 0x00, Fault Syndrome 0x00
Jun 17 12:49:58 ceph3 kernel: [ 2.468037] umem 0000:02:01.0: I/O error on sector 0/4096
Jun 17 12:49:58 ceph3 kernel: [ 2.473517] umem 0000:02:01.0: DMAstat - ANY_ERR MBE_ERR CHAIN_COMPLETE DMA_COMPLETE
Jun 17 12:49:58 ceph3 kernel: [ 2.473525] Buffer I/O error on device umema, logical block 0
Jun 17 12:49:58 ceph3 kernel: [ 2.479499] umem 0000:02:01.0: DMAstat - ANY_ERR MBE_ERR CHAIN_COMPLETE DMA_COMPLETE
Jun 17 12:49:58 ceph3 kernel: [ 2.479506] umem 0000:02:01.0: Memory access error detected (err count 0)
Jun 17 12:49:58 ceph3 kernel: [ 2.483350] umem 0000:02:01.0: Multi-bit EDC error
Jun 17 12:49:58 ceph3 kernel: [ 2.483350] umem 0000:02:01.0: Fault Address 0x0000000ff8, Fault Data 0xfff7fffdffffffff
Jun 17 12:49:58 ceph3 kernel: [ 2.483350] umem 0000:02:01.0: Fault Check 0x00, Fault Syndrome 0x00
Jun 17 12:49:58 ceph3 kernel: [ 2.510375] umem 0000:02:01.0: I/O error on sector 0/4096
Jun 17 12:49:58 ceph3 kernel: [ 2.515856] umem 0000:02:01.0: DMAstat - ANY_ERR MBE_ERR CHAIN_COMPLETE DMA_COMPLETE
Jun 17 12:49:58 ceph3 kernel: [ 2.515863] Buffer I/O error on device umema, logical block 0
Jun 17 12:49:58 ceph3 kernel: [ 2.521769] ldm_validate_partition_table(): Disk read failed.
Jun 17 12:49:58 ceph3 kernel: [ 2.527637] umem 0000:02:01.0: DMAstat - ANY_ERR MBE_ERR CHAIN_COMPLETE DMA_COMPLETE
Jun 17 12:49:58 ceph3 kernel: [ 2.527644] umem 0000:02:01.0: Memory access error detected (err count 0)
Jun 17 12:49:58 ceph3 kernel: [ 2.531590] umem 0000:02:01.0: Multi-bit EDC error
Jun 17 12:49:58 ceph3 kernel: [ 2.531590] umem 0000:02:01.0: Fault Address 0x0000000ff8, Fault Data 0xfff7fffdffffffff
Jun 17 12:49:58 ceph3 kernel: [ 2.531590] umem 0000:02:01.0: Fault Check 0x00, Fault Syndrome 0x00
Jun 17 12:49:58 ceph3 kernel: [ 2.553992] umem 0000:02:01.0: I/O error on sector 0/4096
Jun 17 12:49:58 ceph3 kernel: [ 2.559466] umem 0000:02:01.0: DMAstat - ANY_ERR MBE_ERR CHAIN_COMPLETE DMA_COMPLETE
Jun 17 12:49:58 ceph3 kernel: [ 2.559473] Buffer I/O error on device umema, logical block 0
Jun 17 12:49:58 ceph3 kernel: [ 2.565371] umem 0000:02:01.0: DMAstat - ANY_ERR MBE_ERR CHAIN_COMPLETE DMA_COMPLETE
Jun 17 12:49:58 ceph3 kernel: [ 2.565378] umem 0000:02:01.0: Memory access error detected (err count 0)
Jun 17 12:49:58 ceph3 kernel: [ 2.569297] umem 0000:02:01.0: Multi-bit EDC error
Jun 17 12:49:58 ceph3 kernel: [ 2.569297] umem 0000:02:01.0: Fault Address 0x0000000ff8, Fault Data 0xfff7fffdffffffff
Jun 17 12:49:58 ceph3 kernel: [ 2.569297] umem 0000:02:01.0: Fault Check 0x00, Fault Syndrome 0x00
Jun 17 12:49:58 ceph3 kernel: [ 2.591729] umem 0000:02:01.0: I/O error on sector 0/4096
Jun 17 12:49:58 ceph3 kernel: [ 2.597212] umem 0000:02:01.0: DMAstat - ANY_ERR MBE_ERR CHAIN_COMPLETE DMA_COMPLETE
Jun 17 12:49:58 ceph3 kernel: [ 2.597220] Buffer I/O error on device umema, logical block 0
Jun 17 12:49:58 ceph3 kernel: [ 2.603117] umem 0000:02:01.0: DMAstat - ANY_ERR MBE_ERR CHAIN_COMPLETE DMA_COMPLETE
Jun 17 12:49:58 ceph3 kernel: [ 2.603124] umem 0000:02:01.0: Memory access error detected (err count 0)
Jun 17 12:49:58 ceph3 kernel: [ 2.607042] umem 0000:02:01.0: Multi-bit EDC error
Jun 17 12:49:58 ceph3 kernel: [ 2.607042] umem 0000:02:01.0: Fault Address 0x0000000ff8, Fault Data 0xfff7fffdffffffff
Jun 17 12:49:58 ceph3 kernel: [ 2.607042] umem 0000:02:01.0: Fault Check 0x00, Fault Syndrome 0x00
Jun 17 12:49:58 ceph3 kernel: [ 2.629472] umem 0000:02:01.0: I/O error on sector 0/4096
Jun 17 12:49:58 ceph3 kernel: [ 2.634955] umem 0000:02:01.0: DMAstat - ANY_ERR MBE_ERR CHAIN_COMPLETE DMA_COMPLETE
Jun 17 12:49:58 ceph3 kernel: [ 2.634962] Buffer I/O error on device umema, logical block 0
Jun 17 12:49:58 ceph3 kernel: [ 2.640849] umem 0000:02:01.0: DMAstat - ANY_ERR MBE_ERR CHAIN_COMPLETE DMA_COMPLETE
Jun 17 12:49:58 ceph3 kernel: [ 2.640856] umem 0000:02:01.0: Memory access error detected (err count 0)
Jun 17 12:49:58 ceph3 kernel: [ 2.644785] umem 0000:02:01.0: Multi-bit EDC error
Jun 17 12:49:58 ceph3 kernel: [ 2.644785] umem 0000:02:01.0: Fault Check 0x00, Fault Syndrome 0x00
Jun 17 12:49:58 ceph3 kernel: [ 2.672688] umem 0000:02:01.0: DMAstat - ANY_ERR MBE_ERR CHAIN_COMPLETE DMA_COMPLETE
Jun 17 12:49:58 ceph3 kernel: [ 2.683375] umem 0000:02:01.0: DMAstat - ANY_ERR MBE_ERR CHAIN_COMPLETE DMA_COMPLETE
Jun 17 12:49:58 ceph3 kernel: [ 2.687328] umem 0000:02:01.0: Fault Check 0x00, Fault Syndrome 0x00
Jun 17 12:49:58 ceph3 kernel: [ 2.715281] umem 0000:02:01.0: DMAstat - ANY_ERR MBE_ERR CHAIN_COMPLETE DMA_COMPLETE
Jun 17 12:49:58 ceph3 kernel: [ 2.719213] umem 0000:02:01.0: Fault Address 0x0000000ff8, Fault Data 0xfff7fffdffffffff
Jun 17 12:49:58 ceph3 kernel: [ 2.741630] umem 0000:02:01.0: I/O error on sector 0/4096
Jun 17 12:49:58 ceph3 kernel: [ 2.747111] umem 0000:02:01.0: DMAstat - ANY_ERR MBE_ERR CHAIN_COMPLETE DMA_COMPLETE
Jun 17 12:49:58 ceph3 kernel: [ 2.747194] umem 0000:02:01.0: DMAstat - ANY_ERR MBE_ERR CHAIN_COMPLETE DMA_COMPLETE
Jun 17 12:49:58 ceph3 kernel: [ 2.747200] umem 0000:02:01.0: Memory access error detected (err count 0)
Jun 17 12:49:58 ceph3 kernel: [ 2.751109] umem 0000:02:01.0: Multi-bit EDC error
Jun 17 12:49:58 ceph3 kernel: [ 2.751109] umem 0000:02:01.0: Fault Address 0x0000003ff8, Fault Data 0xefdfffffffffffff
Jun 17 12:49:58 ceph3 kernel: [ 2.773549] umem 0000:02:01.0: I/O error on sector 24/4096
Jun 17 12:49:58 ceph3 kernel: [ 2.779118] umem 0000:02:01.0: DMAstat - ANY_ERR MBE_ERR CHAIN_COMPLETE DMA_COMPLETE
Jun 17 12:49:58 ceph3 kernel: [ 2.779182] umem 0000:02:01.0: DMAstat - ANY_ERR MBE_ERR CHAIN_COMPLETE DMA_COMPLETE
Jun 17 12:49:58 ceph3 kernel: [ 2.779189] umem 0000:02:01.0: Memory access error detected (err count 0)
Jun 17 12:49:58 ceph3 kernel: [ 2.783116] umem 0000:02:01.0: Multi-bit EDC error
Jun 17 12:49:58 ceph3 kernel: [ 2.783116] umem 0000:02:01.0: Fault Address 0x0000003ff8, Fault Data 0xefdfffffffffffff
Jun 17 12:49:58 ceph3 kernel: [ 2.783116] umem 0000:02:01.0: Fault Check 0x00, Fault Syndrome 0x00
Jun 17 12:49:58 ceph3 kernel: [ 2.805537] umem 0000:02:01.0: I/O error on sector 24/4096
Jun 17 12:49:58 ceph3 kernel: [ 2.811098] umem 0000:02:01.0: DMAstat - ANY_ERR MBE_ERR CHAIN_COMPLETE DMA_COMPLETE
Jun 17 12:49:58 ceph3 kernel: [ 2.811163] umem 0000:02:01.0: DMAstat - ANY_ERR MBE_ERR CHAIN_COMPLETE DMA_COMPLETE
Jun 17 12:49:58 ceph3 kernel: [ 2.811170] umem 0000:02:01.0: Memory access error detected (err count 0)
Jun 17 12:49:58 ceph3 kernel: [ 2.815096] umem 0000:02:01.0: Multi-bit EDC error
Jun 17 12:49:58 ceph3 kernel: [ 2.815096] umem 0000:02:01.0: Fault Address 0x0000000ff8, Fault Data 0xfff7fffdffffffff
Jun 17 12:49:58 ceph3 kernel: [ 2.815096] umem 0000:02:01.0: Fault Check 0x00, Fault Syndrome 0x00
Jun 17 12:49:58 ceph3 kernel: [ 2.837518] umem 0000:02:01.0: I/O error on sector 0/4096
Jun 17 12:49:58 ceph3 kernel: [ 2.843000] umem 0000:02:01.0: DMAstat - ANY_ERR MBE_ERR CHAIN_COMPLETE DMA_COMPLETE
Jun 17 12:49:58 ceph3 kernel: [ 2.843269] unable to read partition table
Jun 17 12:49:58 ceph3 kernel: [ 2.849039] MM: desc_per_page = 128

..config is attached.

sage
From: Andrew Morton on
On Thu, 17 Jun 2010 13:21:36 -0700 (PDT)
Sage Weil <sage(a)newdream.net> wrote:

> Hi,
>
> I started seeing a hang during bootup of a machine with a umem
> (micromemory nvram) card. I bisected it and narrowed it down to commit
> b95a5680 which merged a couple nfsd changes, although strangely reverting
> just b160fdab ('nfsd: nfsd_setattr needs to call commit_metadata') is
> sufficient to make the problem go away.
>
> I'm not quite sure what to make of it. I don't see how the nfsd change
> would affect the umem driver initialization. The machine _is_ netbooting
> (kernel via PXE, nfs root), though.

gee, who maintains umem? Neil wrote it eight years ago ;)

> When it hangs, I see
>
> [ 1.069553] v2.3 : Micro Memory(tm) PCI memory board block driver
> [ 1.075780] umem 0000:02:01.0: can't find IRQ for PCI INT C; probably buggy MP table
> [ 1.083633] umem 0000:02:01.0: Micro Memory(tm) controller found (PCI Mem Module (Battery Backup))
> [ 1.092762] umem 0000:02:01.0: CSR 0xfc9ffc00 -> 0xffffc90001466c00 (0x100)
> [ 1.099880] umem 0000:02:01.0: Size 1048576 KB, Battery 1 Disabled (FAILURE), Battery 2 Disabled (FAILURE)
> [ 1.109745] umem 0000:02:01.0: Window size 16777216 bytes, IRQ 9
> [ 1.115842] umem 0000:02:01.0: memory NOT initialized. Consider over-writing whole device.
> [ 1.125778] umema:
> [ 240.886560] INFO: task swapper:1 blocked for more than 120 seconds.
> [ 240.893186] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 240.901115] swapper D 0000000000000001 0 1 0 0x00000000
> [ 240.908231] ffff8800f8da1b50 0000000000000046 ffff8800f8da1ac0 ffff8800f8da1fd8
> [ 240.916027] ffff8800f8d80050 0000000000004000 0000000000004000 00000000001d2180
> [ 240.923819] 00000000001d2180 ffff8800f8da1fd8 ffff8800f8da1fd8 00000000001d2180
> [ 240.931611] Call Trace:
> [ 240.934133] [<ffffffff8144f96d>] ? _raw_spin_unlock_irqrestore+0x4c/0x68
> [ 240.941011] [<ffffffff812a99ab>] ? mm_unplug_device+0x47/0x50
> [ 240.946929] [<ffffffff8144cb84>] io_schedule+0x38/0x4d
> [ 240.952238] [<ffffffff810802d0>] sync_page+0x4c/0x50
> [ 240.957370] [<ffffffff8144cf9b>] __wait_on_bit_lock+0x42/0x8b
> [ 240.963288] [<ffffffff81080284>] ? sync_page+0x0/0x50
> [ 240.968508] [<ffffffff81080270>] __lock_page+0x64/0x6b
> [ 240.973821] [<ffffffff8104b500>] ? wake_bit_function+0x0/0x2a
> [ 240.979741] [<ffffffff81080796>] do_read_cache_page+0xd3/0x135
> [ 240.985745] [<ffffffff810da132>] ? blkdev_readpage+0x0/0x15
> [ 240.991492] [<ffffffff81080834>] read_cache_page_async+0x17/0x19
> [ 240.997671] [<ffffffff8108083f>] read_cache_page+0x9/0x13
> [ 241.003244] [<ffffffff81102a7b>] read_dev_sector+0x2e/0x93
> [ 241.008903] [<ffffffff8110397c>] ? adfspart_check_ICS+0x0/0x19c
> [ 241.014997] [<ffffffff811039b6>] adfspart_check_ICS+0x3a/0x19c
> [ 241.021001] [<ffffffff81432011>] ? kmemleak_alloc+0x5b/0xa2
> [ 241.026748] [<ffffffff810ab6d9>] ? kmem_cache_alloc+0x14f/0x17d
> [ 241.032842] [<ffffffff8110397c>] ? adfspart_check_ICS+0x0/0x19c
> [ 241.038934] [<ffffffff81103778>] rescan_partitions+0x196/0x39a
> [ 241.044940] [<ffffffff8121a24e>] ? disk_get_part+0x74/0xbc
> [ 241.050600] [<ffffffff810da63a>] __blkdev_get+0x271/0x365
> [ 241.056172] [<ffffffff81222b14>] ? kobject_put+0x47/0x4c
> [ 241.061658] [<ffffffff810da739>] blkdev_get+0xb/0xd
> [ 241.066708] [<ffffffff81103121>] register_disk+0xbd/0x11f
> [ 241.072274] [<ffffffff8121a3be>] add_disk+0xb8/0x116
> [ 241.077414] [<ffffffff8193abbf>] mm_init+0x126/0x19e
> [ 241.082556] [<ffffffff8193aa99>] ? mm_init+0x0/0x19e
> [ 241.087693] [<ffffffff810001f0>] do_one_initcall+0x5a/0x14f
> [ 241.093440] [<ffffffff81914908>] kernel_init+0x148/0x1d2
> [ 241.098925] [<ffffffff81003794>] kernel_thread_helper+0x4/0x10
> [ 241.104933] [<ffffffff8102cd00>] ? can_nice+0x19/0x3a
> [ 241.110157] [<ffffffff8144fcc0>] ? restore_args+0x0/0x30
> [ 241.115644] [<ffffffff819147c0>] ? kernel_init+0x0/0x1d2
> [ 241.121128] [<ffffffff81003790>] ? kernel_thread_helper+0x0/0x10
> [ 241.127300] 1 lock held by swapper/1:
> [ 241.131046] #0: (&bdev->bd_mutex){+.+.+.}, at: [<ffffffff810da428>] __blkdev_get+0x5f/0x365
>
> and with the above commit reverted, I get a 'normal' umem driver init (the
> umem errors/warnings are normal.. the batteries aren't connected and the
> card isn't being used):

Given that the kernel is still running initcalls, nfsd hasn't done
anything yet. So it might be a weird ordering thing, or someone has
scribbled on some memory somewhere and shuffling things around in nfsd
is what caused the memory scribble to scrible on something which
someone cares about.

Ugly. Perhaps try enabling every kernel debug option you can lay your
hands on?



> Jun 17 12:49:58 ceph3 kernel: [ 2.270121] v2.3 : Micro Memory(tm) PCI memory board block driver
> Jun 17 12:49:58 ceph3 kernel: [ 2.276360] umem 0000:02:01.0: PCI INT A -> GSI 20 (level, low) -> IRQ 20
> Jun 17 12:49:58 ceph3 kernel: [ 2.283237] umem 0000:02:01.0: Micro Memory(tm) controller found (PCI Mem Module (Battery Backup))
> Jun 17 12:49:58 ceph3 kernel: [ 2.292366] umem 0000:02:01.0: CSR 0xfc9ffc00 -> 0xffffc90001478c00 (0x100)
> Jun 17 12:49:58 ceph3 kernel: [ 2.299476] umem 0000:02:01.0: Size 1048576 KB, Battery 1 Disabled (FAILURE), Battery 2 Disabled (FAILURE)
> Jun 17 12:49:58 ceph3 kernel: [ 2.309507] umem 0000:02:01.0: Window size 16777216 bytes, IRQ 20
> Jun 17 12:49:58 ceph3 kernel: [ 2.315691] umem 0000:02:01.0: memory NOT initialized. Consider over-writing whole device.
> Jun 17 12:49:58 ceph3 kernel: [ 2.325697] umema:
> Jun 17 12:49:58 ceph3 kernel: [ 2.328102] umem 0000:02:01.0: DMAstat - ANY_ERR MBE_ERR CHAIN_COMPLETE DMA_COMPLETE
> Jun 17 12:49:58 ceph3 kernel: [ 2.328239] umem 0000:02:01.0: Memory access error detected (err count 0)
> Jun 17 12:49:58 ceph3 kernel: [ 2.328239] umem 0000:02:01.0: Multi-bit EDC error
> Jun 17 12:49:58 ceph3 kernel: [ 2.328239] umem 0000:02:01.0: Fault Address 0x0000000ff8, Fault Data 0xfff7fffdffffffff
> Jun 17 12:49:58 ceph3 kernel: [ 2.328239] umem 0000:02:01.0: Fault Check 0x00, Fault Syndrome 0x00
> Jun 17 12:49:58 ceph3 kernel: [ 2.354756] umem 0000:02:01.0: I/O error on sector 0/4096
> Jun 17 12:49:58 ceph3 kernel: [ 2.360235] umem 0000:02:01.0: DMAstat - ANY_ERR MBE_ERR CHAIN_COMPLETE DMA_COMPLETE
> Jun 17 12:49:58 ceph3 kernel: [ 2.360248] Buffer I/O error on device umema, logical block 0
> Jun 17 12:49:58 ceph3 kernel: [ 2.366169] umem 0000:02:01.0: DMAstat - ANY_ERR MBE_ERR CHAIN_COMPLETE DMA_COMPLETE
> Jun 17 12:49:58 ceph3 kernel: [ 2.366175] umem 0000:02:01.0: Memory access error detected (err count 0)
> Jun 17 12:49:58 ceph3 kernel: [ 2.370075] umem 0000:02:01.0: Multi-bit EDC error

There may also be bugs in the umem driver. Even if the IO errors are
bogus, the kernel shouldn't hang up waiting for IO completion as it's
doing here.


--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo(a)vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
From: Neil Brown on
On Thu, 17 Jun 2010 13:47:06 -0700
Andrew Morton <akpm(a)linux-foundation.org> wrote:

> On Thu, 17 Jun 2010 13:21:36 -0700 (PDT)
> Sage Weil <sage(a)newdream.net> wrote:
>
> > Hi,
> >
> > I started seeing a hang during bootup of a machine with a umem
> > (micromemory nvram) card. I bisected it and narrowed it down to commit
> > b95a5680 which merged a couple nfsd changes, although strangely reverting
> > just b160fdab ('nfsd: nfsd_setattr needs to call commit_metadata') is
> > sufficient to make the problem go away.

There are two possible explanations for this.
One is that the breakage is caused be an interaction between a commit in one
branch below the merge, and a commit in the other branch.
The other is that the bug has nothing to do with the code, it is randomly
caused by some hardware timing issue, and the "git bisect" process just lead
you on a random walk through git history.

It could be a combination of the two. Some earlier commit makes the symptom
possible but not probably. 'git bisect' would then lead you to some random
commit after the causal commit.

Did you try each kernel multiple times? Could you?

> >
> > I'm not quite sure what to make of it. I don't see how the nfsd change
> > would affect the umem driver initialization. The machine _is_ netbooting
> > (kernel via PXE, nfs root), though.
>
> gee, who maintains umem? Neil wrote it eight years ago ;)

Well, wrote some of it and got it incorporated upstream.
I still vaguely remember how it works.

>
> > When it hangs, I see
> >
> > [ 1.069553] v2.3 : Micro Memory(tm) PCI memory board block driver
> > [ 1.075780] umem 0000:02:01.0: can't find IRQ for PCI INT C; probably buggy MP table
> > [ 1.083633] umem 0000:02:01.0: Micro Memory(tm) controller found (PCI Mem Module (Battery Backup))
> > [ 1.092762] umem 0000:02:01.0: CSR 0xfc9ffc00 -> 0xffffc90001466c00 (0x100)
> > [ 1.099880] umem 0000:02:01.0: Size 1048576 KB, Battery 1 Disabled (FAILURE), Battery 2 Disabled (FAILURE)
> > [ 1.109745] umem 0000:02:01.0: Window size 16777216 bytes, IRQ 9
> > [ 1.115842] umem 0000:02:01.0: memory NOT initialized. Consider over-writing whole device.
> > [ 1.125778] umema:
> > [ 240.886560] INFO: task swapper:1 blocked for more than 120 seconds.
> > [ 240.893186] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> > [ 240.901115] swapper D 0000000000000001 0 1 0 0x00000000
> > [ 240.908231] ffff8800f8da1b50 0000000000000046 ffff8800f8da1ac0 ffff8800f8da1fd8
> > [ 240.916027] ffff8800f8d80050 0000000000004000 0000000000004000 00000000001d2180
> > [ 240.923819] 00000000001d2180 ffff8800f8da1fd8 ffff8800f8da1fd8 00000000001d2180
> > [ 240.931611] Call Trace:
> > [ 240.934133] [<ffffffff8144f96d>] ? _raw_spin_unlock_irqrestore+0x4c/0x68
> > [ 240.941011] [<ffffffff812a99ab>] ? mm_unplug_device+0x47/0x50

It looks like umem is waiting for the DMA controller on the card to
acknowledge that the DMA is complete.
Maybe the interrupt is getting lost somehow? Shared interrupt line? I guess
we would see some sort of "nobody cared" messaged if it were something like
that.


> > and with the above commit reverted, I get a 'normal' umem driver init (the
> > umem errors/warnings are normal.. the batteries aren't connected and the
> > card isn't being used):

Is this really a reliable effect? Boot several times without the commit and
it works. Add the commit and boot several times and it always fails. Then
remove the commit again and it reliably works?

I don't like to have to ask such basic questions, but it is a really weird
error so I need to be sure to eliminate any mismeasurement.



> There may also be bugs in the umem driver. Even if the IO errors are
> bogus, the kernel shouldn't hang up waiting for IO completion as it's
> doing here.
>

No? Even if it is due to faulty hardware?
Do you think the driver should set a timer and disable the card if it hasn't
heard back for a while?
I guess that might be reasonable, though if it turns out to be faulty
hardware I wouldn't trust it on the buss at all...

NeilBrown
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo(a)vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
From: Andrew Morton on
On Fri, 18 Jun 2010 12:54:20 +1000 Neil Brown <neilb(a)suse.de> wrote:

> > There may also be bugs in the umem driver. Even if the IO errors are
> > bogus, the kernel shouldn't hang up waiting for IO completion as it's
> > doing here.
> >
>
> No? Even if it is due to faulty hardware?
> Do you think the driver should set a timer and disable the card if it hasn't
> heard back for a while?
> I guess that might be reasonable, though if it turns out to be faulty
> hardware I wouldn't trust it on the buss at all...

hm, yes, if a DMA controller goes haywire then adding a timeout
specifically to catch and recover from that one particular hardware
failure mode doesn't seem justified.

If we were going to do that then it should be done centrally at the
block layer with a timer-per-request, tunable on a max(all-end-devices)
basis. blah.

As long as the softlockup detector or NMI watchdog or whatever gives a
useful trace pointing at the problem (as it does) then that's
sufficient.

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo(a)vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
From: Sage Weil on
On Fri, 18 Jun 2010, Neil Brown wrote:
> On Thu, 17 Jun 2010 13:47:06 -0700
> Andrew Morton <akpm(a)linux-foundation.org> wrote:
>
> > On Thu, 17 Jun 2010 13:21:36 -0700 (PDT)
> > Sage Weil <sage(a)newdream.net> wrote:
> >
> > > Hi,
> > >
> > > I started seeing a hang during bootup of a machine with a umem
> > > (micromemory nvram) card. I bisected it and narrowed it down to commit
> > > b95a5680 which merged a couple nfsd changes, although strangely reverting
> > > just b160fdab ('nfsd: nfsd_setattr needs to call commit_metadata') is
> > > sufficient to make the problem go away.
>
> There are two possible explanations for this.
> One is that the breakage is caused be an interaction between a commit in one
> branch below the merge, and a commit in the other branch.

The merge was only 2 commits. I tried reverting both and b160fdab was the
winner.

> The other is that the bug has nothing to do with the code, it is randomly
> caused by some hardware timing issue, and the "git bisect" process just lead
> you on a random walk through git history.
>
> It could be a combination of the two. Some earlier commit makes the symptom
> possible but not probably. 'git bisect' would then lead you to some random
> commit after the causal commit.
>
> Did you try each kernel multiple times? Could you?

I just reverified 3x again, and the behavior is consistent. v2.6.35-rc3
fails, and reverting b160fdab does not. I also did a make clean.

However, I took Andrew's suggestion and turned on some more random debug
options, and with that .config v2.6.35-rc3 does not fai. The diff is

4c4
< # Wed Jun 16 12:03:35 2010
---
> # Thu Jun 17 20:40:31 2010
2000c2000
< # CONFIG_DEBUG_SLAB_LEAK is not set
---
> CONFIG_DEBUG_SLAB_LEAK=y
2043c2043
< # CONFIG_DEBUG_PAGEALLOC is not set
---
> CONFIG_DEBUG_PAGEALLOC=y
2088c2088
< # CONFIG_DEBUG_PER_CPU_MAPS is not set
---
> CONFIG_DEBUG_PER_CPU_MAPS=y
2090c2090,2091
< # CONFIG_DEBUG_RODATA is not set
---
> CONFIG_DEBUG_RODATA=y
> CONFIG_DEBUG_RODATA_TEST=y
2092c2093
< # CONFIG_IOMMU_DEBUG is not set
---
> CONFIG_IOMMU_DEBUG=y
2104c2105
< # CONFIG_DEBUG_BOOT_PARAMS is not set
---
> CONFIG_DEBUG_BOOT_PARAMS=y
2264a2266
> # CONFIG_CPUMASK_OFFSTACK is not set

Both .config's are attached.

I wonder if zeroing out the memory (and clearing those umem errors) will
change things, but once I do that I may not be able to reproduce this
hang.

I guess at this point I'll walk through those options one by one to see
which one changes the behavior.

sage




> > > When it hangs, I see
> > >
> > > [ 1.069553] v2.3 : Micro Memory(tm) PCI memory board block driver
> > > [ 1.075780] umem 0000:02:01.0: can't find IRQ for PCI INT C; probably buggy MP table
> > > [ 1.083633] umem 0000:02:01.0: Micro Memory(tm) controller found (PCI Mem Module (Battery Backup))
> > > [ 1.092762] umem 0000:02:01.0: CSR 0xfc9ffc00 -> 0xffffc90001466c00 (0x100)
> > > [ 1.099880] umem 0000:02:01.0: Size 1048576 KB, Battery 1 Disabled (FAILURE), Battery 2 Disabled (FAILURE)
> > > [ 1.109745] umem 0000:02:01.0: Window size 16777216 bytes, IRQ 9
> > > [ 1.115842] umem 0000:02:01.0: memory NOT initialized. Consider over-writing whole device.
> > > [ 1.125778] umema:
> > > [ 240.886560] INFO: task swapper:1 blocked for more than 120 seconds.
> > > [ 240.893186] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> > > [ 240.901115] swapper D 0000000000000001 0 1 0 0x00000000
> > > [ 240.908231] ffff8800f8da1b50 0000000000000046 ffff8800f8da1ac0 ffff8800f8da1fd8
> > > [ 240.916027] ffff8800f8d80050 0000000000004000 0000000000004000 00000000001d2180
> > > [ 240.923819] 00000000001d2180 ffff8800f8da1fd8 ffff8800f8da1fd8 00000000001d2180
> > > [ 240.931611] Call Trace:
> > > [ 240.934133] [<ffffffff8144f96d>] ? _raw_spin_unlock_irqrestore+0x4c/0x68
> > > [ 240.941011] [<ffffffff812a99ab>] ? mm_unplug_device+0x47/0x50
>
> It looks like umem is waiting for the DMA controller on the card to
> acknowledge that the DMA is complete.
> Maybe the interrupt is getting lost somehow? Shared interrupt line? I guess
> we would see some sort of "nobody cared" messaged if it were something like
> that.
>
>
> > > and with the above commit reverted, I get a 'normal' umem driver init (the
> > > umem errors/warnings are normal.. the batteries aren't connected and the
> > > card isn't being used):
>
> Is this really a reliable effect? Boot several times without the commit and
> it works. Add the commit and boot several times and it always fails. Then
> remove the commit again and it reliably works?
>
> I don't like to have to ask such basic questions, but it is a really weird
> error so I need to be sure to eliminate any mismeasurement.
>
>
>
> > There may also be bugs in the umem driver. Even if the IO errors are
> > bogus, the kernel shouldn't hang up waiting for IO completion as it's
> > doing here.
> >
>
> No? Even if it is due to faulty hardware?
> Do you think the driver should set a timer and disable the card if it hasn't
> heard back for a while?
> I guess that might be reasonable, though if it turns out to be faulty
> hardware I wouldn't trust it on the buss at all...
>
> NeilBrown
>
>