Jens: can this be a plugging issue?
The following command seems to block for ever:
# mount /home
It is an ext3 fs on top of /dev/md0, RAID1.
The call trace is:
mount D 000000210a34f3b6 5488 5574 5555 (NOTLB)
ffff8100799718c8 0000000000000046 0000000000000000 0000000000000286
0000000000000000 0000000000000286 ffff81007dc67220 0000000000000020
0000000000000008 ffff810037c42040 ffffffff813a74e0 0000000000001441
Call Trace:
[<ffffffff81061b5a>] getnstimeofday+0x3a/0xa0
[<ffffffff810699d8>] io_schedule+0x98/0xd0
[<ffffffff810f1619>] sleep_on_buffer+0x9/0x10
[<ffffffff81069c95>] __wait_on_bit+0x45/0x80
[<ffffffff810f1610>] sleep_on_buffer+0x0/0x10
[<ffffffff810f1610>] sleep_on_buffer+0x0/0x10
[<ffffffff81069d48>] out_of_line_wait_on_bit+0x78/0x90
[<ffffffff810a25f0>] wake_bit_function+0x0/0x40
[<ffffffff8104f5e0>] __wait_on_buffer+0x20/0x30
[<ffffffff8103ecbd>] sync_dirty_buffer+0xad/0xf0
[<ffffffff8111957a>] ext3_commit_super+0x6a/0x80
[<ffffffff81119ef6>] ext3_setup_super+0x106/0x1c0
[<ffffffff8103f5de>] d_instantiate+0x9e/0xb0
[<ffffffff8111bf94>] ext3_fill_super+0x12f4/0x1650
[<ffffffff810de747>] get_sb_bdev+0x117/0x180
[<ffffffff8111aca0>] ext3_fill_super+0x0/0x1650
[<ffffffff81119363>] ext3_get_sb+0x13/0x20
[<ffffffff810de150>] vfs_kern_mount+0xc0/0x160
[<ffffffff810de25a>] do_kern_mount+0x4a/0x70
[<ffffffff810e8fce>] do_mount+0x73e/0x7c0
[<ffffffff8106c23b>] _read_unlock_irq+0x2b/0x40
[<ffffffff8101c42f>] bad_range+0x1f/0x80
[<ffffffff8100a4a7>] get_page_from_freelist+0x307/0x600
[<ffffffff810240bb>] __up_read+0x8b/0xa0
[<ffffffff8100f8f5>] __alloc_pages+0x75/0x320
[<ffffffff81016a79>] alloc_pages_current+0xb9/0xd0
[<ffffffff81051ad4>] sys_mount+0x94/0xf0
[<ffffffff8106b8b1>] trace_hardirqs_on_thunk+0x35/0x37
[<ffffffff8106511e>] system_call+0x7e/0x83
My precious data!
After that, the system just refuses to shutdown or sync:
shutdown D 0000004f59251224 4880 5622 5576 (NOTLB)
ffff8100796cfe78 0000000000000046 0000000000000000 ffffffff8104d0c2
0000000000000000 0000000000000246 0000000000000000 0000000000000246
0000000000000006 ffff810079082080 ffffffff813a74e0 000000000000545a
Call Trace:
[<ffffffff8104d0c2>] pagevec_lookup_tag+0x22/0x30
[<ffffffff8106b775>] __down_read+0x95/0xb4
[<ffffffff810a4da1>] down_read+0x41/0x50
[<ffffffff810ee4f8>] __sync_inodes+0x78/0x120
[<ffffffff810c57a0>] background_writeout+0x0/0xd0
[<ffffffff810ee5c1>] sync_inodes+0x21/0x50
[<ffffffff810f0efa>] do_sync+0x1a/0x60
[<ffffffff810f0f4e>] sys_sync+0xe/0x20
[<ffffffff8106511e>] system_call+0x7e/0x83
sync D 00000061fa86adc8 5680 5649 5624 (NOTLB)
ffff8100789abe78 0000000000000046 0000000000000000 ffffffff8104d0c2
0000000000000000 0000000000000246 0000000000000000 0000000000000246
0000000000000008 ffff81007842e0c0 ffffffff813a74e0 0000000000002b68
Call Trace:
[<ffffffff8104d0c2>] pagevec_lookup_tag+0x22/0x30
[<ffffffff8106b775>] __down_read+0x95/0xb4
[<ffffffff810a4da1>] down_read+0x41/0x50
[<ffffffff810ee4f8>] __sync_inodes+0x78/0x120
[<ffffffff810c57a0>] background_writeout+0x0/0xd0
[<ffffffff810ee5c1>] sync_inodes+0x21/0x50
[<ffffffff810f0efa>] do_sync+0x1a/0x60
[<ffffffff810f0f4e>] sys_sync+0xe/0x20
[<ffffffff8106511e>] system_call+0x7e/0x83
Showing all locks held in the system:
2 locks held by init/1:
#0: (tty_mutex){--..}, at: [<ffffffff8106a5e5>] mutex_lock+0x25/0x30
#1: (&sysfs_inode_imutex_key){--..}, at: [<ffffffff8106a5e5>] mutex_lock+0x25/0x30
Thanks,
Wu
On Sat, 6 Jan 2007 10:50:02 +0800
Fengguang Wu <[email protected]> wrote:
> Jens: can this be a plugging issue?
>
> The following command seems to block for ever:
> # mount /home
>
> It is an ext3 fs on top of /dev/md0, RAID1.
http://userweb.kernel.org/~akpm/2.6.20-rc3-mm1x.bz2 is basically 2.6.20-rc3-mm1,
minus git-block.patch. Can you and Torsten please test that, see if the hangs
go away?
Thanks.
On Fri, Jan 05, 2007 at 07:59:11PM -0800, Andrew Morton wrote:
> On Sat, 6 Jan 2007 10:50:02 +0800
> Fengguang Wu <[email protected]> wrote:
>
> > Jens: can this be a plugging issue?
> >
> > The following command seems to block for ever:
> > # mount /home
> >
> > It is an ext3 fs on top of /dev/md0, RAID1.
>
> http://userweb.kernel.org/~akpm/2.6.20-rc3-mm1x.bz2 is basically 2.6.20-rc3-mm1,
> minus git-block.patch. Can you and Torsten please test that, see if the hangs
> go away?
Yes, now it mounts OK.
Thanks.
On Saturday 06 January 2007 04:59, Andrew Morton wrote:
>
> http://userweb.kernel.org/~akpm/2.6.20-rc3-mm1x.bz2 is basically
> 2.6.20-rc3-mm1, minus git-block.patch. Can you and Torsten please test
> that, see if the hangs go away?
Works for me too.
Also the locking imbalance reported in Bugzilla-Bug 7775 has disapeared:
[ 24.587727] =====================================
[ 24.606374] [ BUG: bad unlock balance detected! ]
[ 24.620506] -------------------------------------
[ 24.634639] swapper/0 is trying to release lock (inode_lock) at:
[ 24.652797] [<c0184738>] generic_sync_sb_inodes+0xa8/0x2d0
[ 24.669345] but there are no more locks to release!
[ 24.683997]
[ 24.683998] other info that might help us debug this:
[ 24.703690] 1 lock held by swapper/0:
[ 24.714704] #0: (&type->s_umount_key){--..}, at: [<c0168fcc>]
sget+0x1cc/0x370
[ 24.737279]
[ 24.737280] stack backtrace:
[ 24.750452] [<c0138274>] print_unlock_inbalance_bug+0x104/0x120
[ 24.768558] [<c0184738>] generic_sync_sb_inodes+0xa8/0x2d0
[ 24.785366] [<c013942a>] trace_hardirqs_on+0xba/0x160
[ 24.800876] [<c012d9a8>] __kernel_text_address+0x18/0x30
[ 24.817162] [<c0104f66>] dump_trace+0x56/0xa0
[ 24.830594] [<c010a4bc>] save_stack_trace+0x1c/0x40
[ 24.845583] [<c01378b0>] save_trace+0x40/0xa0
[ 24.859013] [<c013795b>] add_lock_to_list+0x4b/0xc0
[ 24.874004] [<c0184738>] generic_sync_sb_inodes+0xa8/0x2d0
[ 24.890812] [<c0184738>] generic_sync_sb_inodes+0xa8/0x2d0
[ 24.907619] [<c013abee>] lock_release+0x8e/0x180
[ 24.921830] [<c041fd34>] _spin_unlock+0x14/0x20
[ 24.935780] [<c0184738>] generic_sync_sb_inodes+0xa8/0x2d0
[ 24.952589] [<c0184a03>] sync_inodes_sb+0x83/0xa0
[ 24.967058] [<c016917a>] __fsync_super+0xa/0x70
[ 24.980983] [<c01691e8>] fsync_super+0x8/0x20
[ 24.994387] [<c016922c>] do_remount_sb+0x2c/0x120
[ 25.008858] [<c01697f1>] get_sb_single+0x61/0xd0
[ 25.023067] [<c01a5540>] sysfs_fill_super+0x0/0xb0
[snip]
I now see this, but the system works:
[ 11.800000] Freeing unused kernel memory: 204k freed
[ 35.300000]
[ 35.300000] =============================================
[ 35.300000] [ INFO: possible recursive locking detected ]
[ 35.300000] 2.6.20-rc3-mm1x #0
[ 35.300000] ---------------------------------------------
[ 35.300000] mount/3795 is trying to acquire lock:
[ 35.300000] (&(&ip->i_lock)->mr_lock){----}, at: [<c020a1f1>]
xfs_ilock+0x71/0xa0
[ 35.300000]
[ 35.300000] but task is already holding lock:
[ 35.300000] (&(&ip->i_lock)->mr_lock){----}, at: [<c020a1f1>]
xfs_ilock+0x71/0xa0
[ 35.300000]
[ 35.300000] other info that might help us debug this:
[ 35.300000] 2 locks held by mount/3795:
[ 35.300000] #0: (&inode->i_mutex){--..}, at: [<c01721df>]
open_namei+0xef/0x610
[ 35.300000] #1: (&(&ip->i_lock)->mr_lock){----}, at: [<c020a1f1>]
xfs_ilock+0x71/0xa0
[ 35.300000]
[ 35.300000] stack backtrace:
[ 35.300000] [<c013a256>] __lock_acquire+0xa96/0x1020
[ 35.300000] [<c01393fa>] debug_check_no_locks_freed+0xca/0x180
[ 35.300000] [<c013a837>] lock_acquire+0x57/0x70
[ 35.300000] [<c020a1f1>] xfs_ilock+0x71/0xa0
[ 35.300000] [<c0133c3d>] down_write+0x3d/0x60
[ 35.300000] [<c020a1f1>] xfs_ilock+0x71/0xa0
[ 35.300000] [<c020a1f1>] xfs_ilock+0x71/0xa0
[ 35.300000] [<c020ae43>] xfs_iget+0x463/0x6f0
[ 35.300000] [<c02247e4>] xfs_trans_iget+0x104/0x170
[ 35.300000] [<c020f4ce>] xfs_ialloc+0xce/0x540
[ 35.300000] [<c0225395>] xfs_dir_ialloc+0x85/0x2e0
[ 35.300000] [<c020a1f1>] xfs_ilock+0x71/0xa0
[ 35.300000] [<c0133c3d>] down_write+0x3d/0x60
[ 35.300000] [<c022c125>] xfs_create+0x395/0x6c0
[ 35.300000] [<c020a155>] xfs_iunlock+0x75/0x90
[ 35.300000] [<c0236901>] xfs_vn_mknod+0x2c1/0x480
[ 35.300000] [<c01632c6>] kmem_cache_free+0x66/0x90
[ 35.300000] [<c013928a>] trace_hardirqs_on+0xba/0x160
[ 35.300000] [<c01f62e4>] xfs_da_brelse+0x74/0xc0
[ 35.300000] [<c01fd7f7>] xfs_dir2_leaf_lookup_int+0x237/0x270
[ 35.300000] [<c01fdd0e>] xfs_dir2_leaf_lookup+0x1e/0xa0
[ 35.300000] [<c01fa59e>] xfs_dir_lookup+0xee/0x100
[ 35.300000] [<c0229456>] xfs_access+0x26/0x50
[ 35.300000] [<c0178450>] d_rehash+0x20/0x50
[ 35.300000] [<c017926a>] d_alloc+0x12a/0x1d0
[ 35.300000] [<c016f374>] vfs_create+0xd4/0x130
[ 35.300000] [<c01726ab>] open_namei+0x5bb/0x610
[ 35.300000] [<c0165a0f>] get_unused_fd+0x1f/0xb0
[ 35.300000] [<c0154539>] __handle_mm_fault+0x179/0x8b0
[ 35.300000] [<c0165d4e>] do_filp_open+0x2e/0x60
[ 35.300000] [<c041fef4>] _spin_unlock+0x14/0x20
[ 35.300000] [<c0165a8c>] get_unused_fd+0x9c/0xb0
[ 35.300000] [<c0165dca>] do_sys_open+0x4a/0xe0
[ 35.300000] [<c0165e9c>] sys_open+0x1c/0x20
[ 35.300000] [<c0104022>] sysenter_past_esp+0x5f/0x99
[ 35.300000] =======================
[ 37.390000] kjournald starting. Commit interval 5 seconds
On Sat, Jan 06 2007, Torsten Kaiser wrote:
> On Saturday 06 January 2007 04:59, Andrew Morton wrote:
> >
> > http://userweb.kernel.org/~akpm/2.6.20-rc3-mm1x.bz2 is basically
> > 2.6.20-rc3-mm1, minus git-block.patch. Can you and Torsten please test
> > that, see if the hangs go away?
>
> Works for me too.
Torsten, can you test XFS with barriers disabled? I have a feeling that
is where the problem lies.
--
Jens Axboe
On Saturday 06 January 2007 11:02, Jens Axboe wrote:
> On Sat, Jan 06 2007, Torsten Kaiser wrote:
> > On Saturday 06 January 2007 04:59, Andrew Morton wrote:
> > > http://userweb.kernel.org/~akpm/2.6.20-rc3-mm1x.bz2 is basically
> > > 2.6.20-rc3-mm1, minus git-block.patch. Can you and Torsten please
> > > test that, see if the hangs go away?
> >
> > Works for me too.
>
> Torsten, can you test XFS with barriers disabled? I have a feeling that
> is where the problem lies.
With your patch from Bug 7775: Same hang detected by NMI watchdog
Pure rc3-mm1: Now triggers also the NMI watchdog:
[ 34.942639] ACPI: (supports<6>Time: tsc clocksource has been installed.
[ 34.962607] Clock event device lapic disabled
[ 34.975717] Clock event device pit configured with caps set: 08
[ 34.993526] Switched to high resolution mode on CPU 0
[ 35.008720] Time: pit clocksource has been installed.
[ 35.028823] S0 S1 S4 S5)
[ 35.052336] XFS mounting filesystem sdb6
[ 40.940722] BUG: NMI Watchdog detected LOCKUP on CPU0, eip c0109ce5,
registers:
[ 40.962737] Modules linked in:
[ 40.971991] CPU: 0
[ 40.971992] EIP: 0060:[<c0109ce5>] Not tainted VLI
[ 40.971995] EFLAGS: 00000046 (2.6.20-rc3-mm1 #3)
[ 41.009208] EIP is at pit_read+0x25/0xa0
[ 41.021008] eax: 00000005 ebx: 00000052 ecx: 00000000 edx:
00000082
[ 41.041376] esi: 0009ba52 edi: 3922e0ca ebp: 0004fc3a esp:
dff839e0
[ 41.061742] ds: 007b es: 007b fs: 00d8 gs: 0000 ss: 0068
[ 41.079253] Process swapper (pid: 1, ti=dff82000 task=dff81510
task.ti=dff82000)
[ 41.100915] Stack: 0004fc3a dff83a10 c01244c1 dff83a10 0004fc3a dff83a10
3922e0ca dff83ad8
[ 41.126659] c0133081 00000000 dff83a30 c01330c6 459fa082 139adb41
c052f080 80a5e194
[ 41.152378] c013344f 00000001 c052f130 c052f130 00000002 00000612
c052f130 80a5e194
[ 41.178099] Call Trace:
[ 41.186077] [<c01244c1>] getnstimeofday+0x31/0xc0
[ 41.200569] [<c0133081>] ktime_get_ts+0x11/0x40
[ 41.214521] [<c01330c6>] ktime_get+0x16/0x40
[ 41.227692] [<c013344f>] hrtimer_sched_tick+0x2f/0xd0
[ 41.243199] [<c0133a58>] hrtimer_interrupt+0x148/0x1e0
[ 41.258969] [<c010744f>] timer_interrupt+0x2f/0x40
[ 41.273698] [<c0143c60>] handle_IRQ_event+0x20/0x50
[ 41.288689] [<c0145391>] handle_level_irq+0x81/0x110
[ 41.303937] [<c01067f6>] do_IRQ+0x46/0x80
[ 41.316329] [<c011c4b1>] vprintk+0x201/0x2f0
[ 41.329501] [<c0104a96>] common_interrupt+0x2e/0x34
[ 41.344490] [<c023a88d>] cmn_err+0x9d/0xb0
[ 41.357143] [<c04202b7>] _spin_unlock_irqrestore+0x47/0x60
[ 41.373976] [<c023a88d>] cmn_err+0x9d/0xb0
[ 41.386627] [<c0218218>] xfs_log_mount+0x48/0x5d0
[ 41.401098] [<c021fbbd>] xfs_mountfs+0xb1d/0xfa0
[ 41.415306] [<c041fe09>] _spin_lock+0x29/0x40
[ 41.428737] [<c0231e93>] xfs_setsize_buftarg_flags+0x33/0xc0
[ 41.446066] [<c0227391>] xfs_mount+0x641/0x9c0
[ 41.459758] [<c0226d50>] xfs_mount+0x0/0x9c0
[ 41.472928] [<c0239e92>] vfs_mount+0x22/0x30
[ 41.486099] [<c0239cb8>] xfs_fs_fill_super+0x78/0x1e0
[ 41.501608] [<c025cf0f>] snprintf+0x1f/0x30
[ 41.514518] [<c01a2222>] disk_name+0x92/0xc0
[ 41.527689] [<c0169bd4>] get_sb_bdev+0x104/0x140
[ 41.541900] [<c0238ed0>] xfs_fs_get_sb+0x20/0x30
[ 41.556109] [<c0239c40>] xfs_fs_fill_super+0x0/0x1e0
[ 41.572189] [<c0169696>] vfs_kern_mount+0xb6/0x130
[ 41.586920] [<c0169769>] do_kern_mount+0x39/0x60
[ 41.601130] [<c017ec5c>] do_mount+0x42c/0x700
[ 41.614560] [<c041fd34>] _spin_unlock+0x14/0x20
[ 41.628513] [<c02585c6>] _atomic_dec_and_lock+0x16/0x60
[ 41.644540] [<c02585e1>] _atomic_dec_and_lock+0x31/0x60
[ 41.660573] [<c014c27a>] __get_free_pages+0x1a/0x40
[ 41.675584] [<c017d4d0>] copy_mount_options+0x40/0x150
[ 41.691354] [<c017efa2>] sys_mount+0x72/0xb0
[ 41.704524] [<c0576e9e>] mount_block_root+0x8e/0x270
[ 41.719774] [<c0171d57>] sys_mknod+0x27/0x30
[ 41.732946] [<c05770d0>] mount_root+0x50/0x90
[ 41.746376] [<c0577222>] prepare_namespace+0x112/0x150
[ 41.762145] [<c016658f>] sys_access+0x1f/0x30
[ 41.775577] [<c0576842>] init+0x132/0x1a0
[ 41.787966] [<c0576710>] init+0x0/0x1a0
[ 41.799840] [<c0576710>] init+0x0/0x1a0
[ 41.811711] [<c0104c2f>] kernel_thread_helper+0x7/0x18
[ 41.827481] =======================
[ 41.838235] Code: 31 00 8d 74 26 00 56 b8 e0 b7 52 c0 53 e8 b4 64 31 00
8b 35 20 e0 52 c0 89 c2 31 c0 e6 43 e6 80 e4 40 e6 80 0f b6 d8 e4 40 e6 80
<0f> b6 c0 c1 e0 08 09 c3 81 fb 9c 2e 00 00 7e 1
[ 41.899752] [ 41.903993]
I used the following kernel commandline:
root=/dev/sdb6 console=ttyS0,38400 console=tty1 lapic rootflags=nobarrier
I also added nobarrier to the fstab entry for my root.
Just to mention it: My system does not use any RAID devices, not even the
drivers are getting complied.
On Sat, Jan 06 2007, Torsten Kaiser wrote:
> On Saturday 06 January 2007 11:02, Jens Axboe wrote:
> > On Sat, Jan 06 2007, Torsten Kaiser wrote:
> > > On Saturday 06 January 2007 04:59, Andrew Morton wrote:
> > > > http://userweb.kernel.org/~akpm/2.6.20-rc3-mm1x.bz2 is basically
> > > > 2.6.20-rc3-mm1, minus git-block.patch. Can you and Torsten please
> > > > test that, see if the hangs go away?
> > >
> > > Works for me too.
> >
> > Torsten, can you test XFS with barriers disabled? I have a feeling that
> > is where the problem lies.
>
> With your patch from Bug 7775: Same hang detected by NMI watchdog
> Pure rc3-mm1: Now triggers also the NMI watchdog:
Ok, thanks for testing, I'll try and reproduce it locally.
--
Jens Axboe
On Sat, Jan 06 2007, Torsten Kaiser wrote:
> On Saturday 06 January 2007 11:02, Jens Axboe wrote:
> > On Sat, Jan 06 2007, Torsten Kaiser wrote:
> > > On Saturday 06 January 2007 04:59, Andrew Morton wrote:
> > > > http://userweb.kernel.org/~akpm/2.6.20-rc3-mm1x.bz2 is basically
> > > > 2.6.20-rc3-mm1, minus git-block.patch. Can you and Torsten please
> > > > test that, see if the hangs go away?
> > >
> > > Works for me too.
> >
> > Torsten, can you test XFS with barriers disabled? I have a feeling that
> > is where the problem lies.
>
> With your patch from Bug 7775: Same hang detected by NMI watchdog
Does this fix it? Only apply this one, not the patch from 7775.
diff --git a/block/ll_rw_blk.c b/block/ll_rw_blk.c
index ec40e44..bae57e0 100644
--- a/block/ll_rw_blk.c
+++ b/block/ll_rw_blk.c
@@ -1542,7 +1542,7 @@ static inline void queue_sync_plugs(request_queue_t *q)
* If the current process is plugged and has barriers submitted,
* we will livelock if we don't unplug first.
*/
- blk_unplug_current();
+ blk_replug_current_nested();
synchronize_qrcu(&q->qrcu);
}
--
Jens Axboe
On Monday 08 January 2007 09:52, Jens Axboe wrote:
> --- a/block/ll_rw_blk.c
> +++ b/block/ll_rw_blk.c
> @@ -1542,7 +1542,7 @@ static inline void
> - blk_unplug_current();
> + blk_replug_current_nested();
Does not help. Dmesg follows:
[ 0.000000] Linux version 2.6.20-rc3-mm1 (root@ariolc) (gcc version
4.1.1 (Gentoo 4.1.1-r3)) #4 Mon Jan 8 18:23:37 CET 2007
[ 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] copy_e820_map() start: 000000000009fc00 size:
0000000000000400 end: 00000000000a0000 type: 2
[ 0.000000] copy_e820_map() start: 00000000000f0000 size:
0000000000010000 end: 0000000000100000 type: 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] copy_e820_map() start: 000000001fff0000 size:
0000000000003000 end: 000000001fff3000 type: 4
[ 0.000000] copy_e820_map() start: 000000001fff3000 size:
000000000000d000 end: 0000000020000000 type: 3
[ 0.000000] copy_e820_map() start: 00000000ffff0000 size:
0000000000010000 end: 0000000100000000 type: 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 - 000000001fff3000 (ACPI NVS)
[ 0.000000] BIOS-e820: 000000001fff3000 - 0000000020000000 (ACPI data)
[ 0.000000] BIOS-e820: 00000000ffff0000 - 0000000100000000 (reserved)
[ 0.000000] 511MB LOWMEM available.
[ 0.000000] Zone PFN ranges:
[ 0.000000] DMA 0 -> 4096
[ 0.000000] Normal 4096 -> 131056
[ 0.000000] early_node_map[1] active PFN ranges
[ 0.000000] 0: 0 -> 131056
[ 0.000000] DMI 2.3 present.
[ 0.000000] ACPI: PM-Timer IO Port: 0x4008
[ 0.000000] Allocating PCI resources starting at 30000000 (gap:
20000000:dfff0000)
[ 0.000000] Detected 1002.314 MHz processor.
[ 26.865802] Built 1 zonelists. Total pages: 130033
[ 26.865807] Kernel command line: root=/dev/sdb6 console=ttyS0,38400
console=tty1 lapic rootflags=nobarrier
[ 26.866203] Local APIC disabled by BIOS -- reenabling.
[ 26.866209] Found and enabled local APIC!
[ 26.866223] Enabling fast FPU save and restore... done.
[ 26.866246] Initializing CPU#0
[ 26.866401] PID hash table entries: 2048 (order: 11, 8192 bytes)
[ 26.867677] Console: colour VGA+ 80x25
[ 27.543779] Lock dependency validator: Copyright (c) 2006 Red Hat, Inc.,
Ingo Molnar
[ 27.567001] ... MAX_LOCKDEP_SUBCLASSES: 8
[ 27.579834] ... MAX_LOCK_DEPTH: 30
[ 27.592407] ... MAX_LOCKDEP_KEYS: 2048
[ 27.605501] ... CLASSHASH_SIZE: 1024
[ 27.618853] ... MAX_LOCKDEP_ENTRIES: 8192
[ 27.631946] ... MAX_LOCKDEP_CHAINS: 16384
[ 27.645300] ... CHAINHASH_SIZE: 8192
[ 27.658392] memory used by lock dependency info: 1096 kB
[ 27.674603] per task-struct memory footprint: 1200 bytes
[ 27.691602] Dentry cache hash table entries: 65536 (order: 6, 262144
bytes)
[ 27.713148] Inode-cache hash table entries: 32768 (order: 5, 131072
bytes)
[ 27.769004] Memory: 511896k/524224k available (3204k kernel code, 11796k
reserved, 1352k data, 204k init, 0k highmem)
[ 27.800844] virtual kernel memory layout:
[ 27.800846] fixmap : 0xfffb7000 - 0xfffff000 ( 288 kB)
[ 27.800849] vmalloc : 0xe0800000 - 0xfffb5000 ( 503 MB)
[ 27.800852] lowmem : 0xc0000000 - 0xdfff0000 ( 511 MB)
[ 27.800855] .init : 0xc0576000 - 0xc05a9000 ( 204 kB)
[ 27.800857] .data : 0xc04211a0 - 0xc05732ac (1352 kB)
[ 27.800860] .text : 0xc0100000 - 0xc04211a0 (3204 kB)
[ 27.916411] Checking if this processor honours the WP bit even in
supervisor mode... Ok.
[ 27.941129] Clock event device pit configured with caps set: 07
[ 28.101036] Calibrating delay using timer specific routine.. 2006.70
BogoMIPS (lpj=10033529)
[ 28.126627] Security Framework v1.0.0 initialized
[ 28.140835] Mount-cache hash table entries: 512
[ 28.154789]
[ 28.154792] =====================================
[ 28.173440] [ BUG: bad unlock balance detected! ]
[ 28.187571] -------------------------------------
[ 28.201705] swapper/0 is trying to release lock (inode_lock) at:
[ 28.219863] [<c0184738>] generic_sync_sb_inodes+0xa8/0x2d0
[ 28.236411] but there are no more locks to release!
[ 28.251063]
[ 28.251064] other info that might help us debug this:
[ 28.270756] 1 lock held by swapper/0:
[ 28.281770] #0: (&type->s_umount_key){--..}, at: [<c0168fcc>]
sget+0x1cc/0x370
[ 28.304344]
[ 28.304346] stack backtrace:
[ 28.317492] [<c0138274>] print_unlock_inbalance_bug+0x104/0x120
[ 28.335598] [<c0184738>] generic_sync_sb_inodes+0xa8/0x2d0
[ 28.352405] [<c013942a>] trace_hardirqs_on+0xba/0x160
[ 28.367915] [<c012d9a8>] __kernel_text_address+0x18/0x30
[ 28.384203] [<c0104f66>] dump_trace+0x56/0xa0
[ 28.397634] [<c010a4bc>] save_stack_trace+0x1c/0x40
[ 28.412624] [<c01378b0>] save_trace+0x40/0xa0
[ 28.426055] [<c013795b>] add_lock_to_list+0x4b/0xc0
[ 28.441044] [<c0184738>] generic_sync_sb_inodes+0xa8/0x2d0
[ 28.457852] [<c0184738>] generic_sync_sb_inodes+0xa8/0x2d0
[ 28.474660] [<c013abee>] lock_release+0x8e/0x180
[ 28.488870] [<c041fdb4>] _spin_unlock+0x14/0x20
[ 28.502821] [<c0184738>] generic_sync_sb_inodes+0xa8/0x2d0
[ 28.519629] [<c0184a03>] sync_inodes_sb+0x83/0xa0
[ 28.534100] [<c016917a>] __fsync_super+0xa/0x70
[ 28.548050] [<c01691e8>] fsync_super+0x8/0x20
[ 28.561480] [<c016922c>] do_remount_sb+0x2c/0x120
[ 28.575949] [<c01697f1>] get_sb_single+0x61/0xd0
[ 28.590159] [<c01a5540>] sysfs_fill_super+0x0/0xb0
[ 28.604890] [<c0169696>] vfs_kern_mount+0xb6/0x130
[ 28.619619] [<c01a5540>] sysfs_fill_super+0x0/0xb0
[ 28.634349] [<c0169723>] kern_mount+0x13/0x20
[ 28.647780] [<c058a22f>] sysfs_init+0x6f/0xb0
[ 28.661211] [<c05897b0>] mnt_init+0xc0/0x200
[ 28.674382] [<c0589387>] vfs_caches_init+0xd7/0x170
[ 28.689372] [<c0576a79>] start_kernel+0x1c9/0x380
[ 28.703842] [<c05764b0>] unknown_bootoption+0x0/0x260
[ 28.719350] =======================
[ 28.730336] CPU: After generic identify, caps: 0183fbff c1c7fbff
00000000 00000000 00000000 00000000 00000000
[ 28.760723] CPU: L1 I Cache: 64K (64 bytes/line), D cache 64K (64
bytes/line)
[ 28.782152] CPU: L2 Cache: 256K (64 bytes/line)
[ 28.795765] CPU: After all inits, caps: 0183fbff c1c7fbff 00000000
00000420 00000000 00000000 00000000
[ 28.824358] Intel machine check architecture supported.
[ 28.840059] Intel machine check reporting enabled on CPU#0.
[ 28.856809] CPU: AMD Athlon(tm) Processor stepping 02
[ 28.872195] Checking 'hlt' instruction... OK.
[ 28.921952] ACPI: Core revision 20060707
[ 28.943079] ACPI: setting ELCR to 0800 (from 0e20)
[ 29.220314] Clock event device pit new caps set: 03
[ 29.234973] Clock event device lapic configured with caps set: 04
[ 29.253277] spurious 8259A interrupt: IRQ7.
[ 29.375572] NET: Registered protocol family 16
[ 29.389225] ACPI: bus type pci registered
[ 29.434373] PCI: PCI BIOS revision 2.10 entry at 0xfb380, last bus=1
[ 29.453460] PCI: Using configuration type 1
[ 29.466033] Setting up standard PCI resources
[ 29.504063] ACPI: Interpreter enabled
[ 29.515113] ACPI: Using PIC for interrupt routing
[ 29.538752] ACPI: PCI Root Bridge [PCI0] (0000:00)
[ 29.553487] ACPI: Assume root bridge [\_SB_.PCI0] bus is 0
[ 29.570517] Disabling VIA memory write queue (PCI ID 0305, rev 03): [55]
81 & 1f -> 01
[ 29.594653] PCI quirk: region 4000-40ff claimed by vt82c586 ACPI
[ 29.613374] PCI quirk: region 6000-607f claimed by vt82c686 HW-mon
[ 29.631984] PCI quirk: region 5000-500f claimed by vt82c686 SMB
[ 29.650263] Boot video device is 0000:01:00.0
[ 29.663437] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0._PRT]
[ 29.715800] ACPI: PCI Interrupt Link [LNKA] (IRQs 1 3 4 5 6 7 10 *11 12
14 15)
[ 29.738915] ACPI: PCI Interrupt Link [LNKB] (IRQs 1 3 4 5 6 7 *10 11 12
14 15)
[ 29.761991] ACPI: PCI Interrupt Link [LNKC] (IRQs 1 3 4 *5 6 7 10 11 12
14 15)
[ 29.785084] ACPI: PCI Interrupt Link [LNKD] (IRQs 1 3 4 5 6 7 10 11 12
14 15) *9
[ 29.808583] Linux Plug and Play Support v0.97 (c) Adam Belay
[ 29.825613] pnp: PnP ACPI init
[ 29.834993] pnp: ACPI device : hid PNP0C01
[ 29.847915] pnp: ACPI device : hid PNP0A03
[ 29.860834] pnp: ACPI device : hid PNP0C02
[ 29.873297] pnp: ACPI device : hid PNP0200
[ 29.885719] pnp: ACPI device : hid PNP0B00
[ 29.898143] pnp: ACPI device : hid PNP0800
[ 29.910597] pnp: ACPI device : hid PNP0C04
[ 29.923364] pnp: ACPI device : hid PNP0700
[ 29.936220] pnp: ACPI device : hid PNP0501
[ 29.949518] pnp: ACPI device : hid PNP0501
[ 29.963065] pnp: ACPI device : hid PNP0400
[ 29.976425] pnp: ACPI device : hid PNP0F13
[ 29.988956] pnp: ACPI device : hid PNP0303
[ 30.001387] pnp: PnP ACPI: found 13 devices
[ 30.014097] Generic PHY: Registered new driver
[ 30.027775] SCSI subsystem initialized
[ 30.039143] libata version 2.00 loaded.
[ 30.050884] usbcore: registered new interface driver usbfs
[ 30.067443] usbcore: registered new interface driver hub
[ 30.083529] usbcore: registered new device driver usb
[ 30.098913] PCI: Using ACPI for IRQ routing
[ 30.111510] PCI: If a device doesn't work, try "pci=routeirq". If it
helps, post a report
[ 30.167247] pnp: the driver 'system' has been registered
[ 30.183306] pnp: match found with the PnP device '00:00' and the
driver 'system'
[ 30.205530] pnp: match found with the PnP device '00:02' and the
driver 'system'
[ 30.228592] ieee1394: Initialized config rom entry `ip1394'
[ 30.245662] PCI: Bridge: 0000:00:01.0
[ 30.256705] IO window: disabled.
[ 30.266963] MEM window: dc000000-ddffffff
[ 30.279562] PREFETCH window: d0000000-d7ffffff
[ 30.293484] PCI: Setting latency timer of device 0000:00:01.0 to 64
[ 30.312368] NET: Registered protocol family 2
[ 30.419670] IP route cache hash table entries: 4096 (order: 2, 16384
bytes)
[ 30.440856] TCP established hash table entries: 16384 (order: 7, 655360
bytes)
[ 30.466123] TCP bind hash table entries: 8192 (order: 6, 360448 bytes)
[ 30.487651] TCP: Hash tables configured (established 16384 bind 8192)
[ 30.507010] TCP reno registered
[ 30.541300] Total HugeTLB memory allocated, 0
[ 30.554592] VFS: Disk quotas dquot_6.5.1
[ 30.566462] Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[ 30.586279] SGI XFS with ACLs, security attributes, no debug enabled
[ 30.605606] SGI XFS Quota Management subsystem
[ 30.619010] io scheduler noop registered
[ 30.630911] io scheduler cfq registered (default)
[ 30.645228] PCI: Disabling Via external APIC routing
[ 30.660182] pci 0000:00:07.2: uhci_check_and_reset_hc: legsup = 0x2000
[ 30.679772] pci 0000:00:07.2: Performing full reset
[ 30.694439] pci 0000:00:07.3: uhci_check_and_reset_hc: legsup = 0x2000
[ 30.714046] pci 0000:00:07.3: Performing full reset
[ 30.729222] ACPI: CPU0 (power states: C1[C1] C2[C2])
[ 30.744396] ACPI: Processor [CPU0] (supports 2 throttling states)
[ 30.879757] Real Time Clock Driver v1.12ac
[ 30.892497] Non-volatile memory driver v1.2
[ 30.905198] Linux agpgart interface v0.101 (c) Dave Jones
[ 30.921627] agpgart: Detected VIA Twister-K/KT133x/KM133 chipset
[ 30.946578] agpgart: AGP aperture is 64M @ 0xd8000000
[ 30.961937] Serial: 8250/16550 driver $Revision: 1.90 $ 1 ports, IRQ
sharing disabled
[ 30.985769] serial8250: ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
[ 31.004434] pnp: the driver 'serial' has been registered
[ 31.020688] pnp: match found with the PnP device '00:08' and the
driver 'serial'
[ 31.043325] 00:08: ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
[ 31.060502] pnp: match found with the PnP device '00:09' and the
driver 'serial'
[ 31.083212] pnp: Device 00:09 disabled.
[ 31.095027] parport_pc: VIA 686A/8231 detected
[ 31.108403] parport_pc: probing current configuration
[ 31.123616] parport_pc: Current parallel port base: 0x378
[ 31.139870] parport0: PC-style at 0x378, irq 7 [PCSPP,TRISTATE,EPP]
[ 31.239036] parport_pc: VIA parallel port: io=0x378, irq=7
[ 31.255908] Floppy drive(s): fd0 is 1.44M
[ 31.282607] FDC 0 is a post-1991 82077
[ 31.295077] fealnx.c:v2.52 Sep-11-2006
[ 31.307212] ACPI: PCI Interrupt Link [LNKA] enabled at IRQ 11
[ 31.324489] PCI: setting IRQ 11 as level-triggered
[ 31.338907] ACPI: PCI Interrupt 0000:00:08.0[A] -> Link [LNKA] -> GSI 11
(level, low) -> IRQ 11
[ 31.365432] eth0: 100/10M Ethernet PCI Adapter at 0001ec00,
00:02:2a:c0:86:2a, IRQ 11.
[ 31.389969] Linux video capture interface: v2.00
[ 31.403875] bttv: driver version 0.9.16 loaded
[ 31.417260] bttv: using 8 buffers with 2080k (520 pages) each for
capture
[ 31.437767] bttv: Bt8xx card found (0).
[ 31.450045] ACPI: PCI Interrupt Link [LNKB] enabled at IRQ 10
[ 31.467312] PCI: setting IRQ 10 as level-triggered
[ 31.481710] ACPI: PCI Interrupt 0000:00:09.0[A] -> Link [LNKB] -> GSI 10
(level, low) -> IRQ 10
[ 31.507986] bttv0: Bt878 (rev 17) at 0000:00:09.0, irq: 10, latency: 32,
mmio: 0xdf001000
[ 31.532663] bttv0: detected: Hauppauge WinTV [card=10], PCI subsystem ID
is 0070:13eb
[ 31.556181] bttv0: using: Hauppauge (bt878) [card=10,autodetected]
[ 31.574780] bttv0: gpio: en=00000000, out=00000000 in=00ffffdb [init]
[ 31.596633] bttv0: Hauppauge/Voodoo msp34xx: reset line init [5]
[ 31.644814] tveeprom 0-0050: Hauppauge model 61344, rev D421, serial#
3902813
[ 31.666259] tveeprom 0-0050: tuner model is Philips FM1216 (idx 21, type
5)
[ 31.687171] tveeprom 0-0050: TV standards PAL(B/G) (eeprom 0x04)
[ 31.705226] tveeprom 0-0050: audio processor is MSP3415 (idx 6)
[ 31.723019] tveeprom 0-0050: has radio
[ 31.734286] bttv0: Hauppauge eeprom indicates model#61344
[ 31.750506] bttv0: using tuner=5
[ 31.760289] bttv0: registered device video0
[ 31.772959] bttv0: registered device vbi0
[ 31.785091] bttv0: registered device radio0
[ 31.797703] bttv0: PLL: 28636363 => 35468950 .. ok
[ 31.851224] input: i2c IR (Hauppauge) as /class/input/input0
[ 31.868249] ir-kbd-i2c: i2c IR (Hauppauge) detected at i2c-0/0-0018/ir0
[bt878 #0 [sw]]
[ 31.899200] msp3400 0-0040: MSP3415D-B3 found @ 0x80 (bt878 #0 [sw])
[ 31.918299] msp3400 0-0040: MSP3415D-B3 supports nicam, mode is
autodetect
[ 31.943906] tuner 0-0061: chip found @ 0xc2 (bt878 #0 [sw])
[ 31.960744] tuner 0-0061: type set to 5 (Philips PAL_BG (FI1216 and
compatibles))
[ 31.983219] tuner 0-0061: type set to 5 (Philips PAL_BG (FI1216 and
compatibles))
[ 32.016366] pata_via 0000:00:07.1: version 0.2.0
[ 32.030449] ata1: PATA max UDMA/66 cmd 0x1F0 ctl 0x3F6 bmdma 0xD000 irq
14
[ 32.051711] ata2: PATA max UDMA/66 cmd 0x170 ctl 0x376 bmdma 0xD008 irq
15
[ 32.072398] scsi0 : pata_via
[ 32.259217] ata1.00: ATA-6, max UDMA/100, 39865392 sectors: LBA
[ 32.277266] ata1.00: ata1: dev 0 multi count 16
[ 32.308574] ata1.01: ATA-7, max UDMA/133, 490234752 sectors: LBA48
[ 32.327402] ata1.01: ata1: dev 1 multi count 16
[ 32.358529] ata1.00: configured for UDMA/66
[ 32.408493] ata1.01: configured for UDMA/66
[ 32.421091] scsi1 : pata_via
[ 32.768278] ata2.00: ATAPI, max MWDMA2
[ 32.958189] ata2.01: ATAPI, max MWDMA2
[ 33.168005] ata2.00: configured for MWDMA2
[ 33.357935] ata2.01: configured for MWDMA2
[ 33.370512] scsi 0:0:0:0: Direct-Access ATA SAMSUNG SV2042H
PK10 PQ: 0 ANSI: 5
[ 33.395582] SCSI device sda: 39865392 512-byte hdwr sectors (20411 MB)
[ 33.415233] sda: Write Protect is off
[ 33.426270] sda: Mode Sense: 00 3a 00 00
[ 33.438126] SCSI device sda: write cache: enabled, read cache: enabled,
doesn't support DPO or FUA
[ 33.465128] SCSI device sda: 39865392 512-byte hdwr sectors (20411 MB)
[ 33.484765] sda: Write Protect is off
[ 33.495788] sda: Mode Sense: 00 3a 00 00
[ 33.507640] SCSI device sda: write cache: enabled, read cache: enabled,
doesn't support DPO or FUA
[ 33.534514] sda: sda1 sda2 < sda5 >
[ 33.566247] sd 0:0:0:0: Attached scsi disk sda
[ 33.579876] scsi 0:0:1:0: Direct-Access ATA Maxtor 6L250R0
BAH4 PQ: 0 ANSI: 5
[ 33.604355] SCSI device sdb: 490234752 512-byte hdwr sectors (251000 MB)
[ 33.624516] sdb: Write Protect is off
[ 33.635552] sdb: Mode Sense: 00 3a 00 00
[ 33.647412] SCSI device sdb: write cache: enabled, read cache: enabled,
doesn't support DPO or FUA
[ 33.674415] SCSI device sdb: 490234752 512-byte hdwr sectors (251000 MB)
[ 33.694566] sdb: Write Protect is off
[ 33.705589] sdb: Mode Sense: 00 3a 00 00
[ 33.717973] SCSI device sdb: write cache: enabled, read cache: enabled,
doesn't support DPO or FUA
[ 33.744860] sdb: sdb1 sdb2 sdb3 sdb4 < sdb5 sdb6 >
[ 33.806173] sd 0:0:1:0: Attached scsi disk sdb
[ 33.820052] scsi 1:0:0:0: CD-ROM SAMSUNG DVD-ROM SD-612S
SS06 PQ: 0 ANSI: 5
[ 33.845084] scsi 1:0:1:0: CD-ROM SAMSUNG CD-R/RW SW-208B
BS04 PQ: 0 ANSI: 5
[ 33.870744] usbmon: debugfs is not available
[ 33.883591] ehci_hcd: block sizes: qh 128 qtd 96 itd 192 sitd 96
[ 33.901728] ohci_hcd: 2006 August 04 USB 1.1 'Open' Host Controller
(OHCI) Driver
[ 33.924192] ohci_hcd: block sizes: ed 64 td 64
[ 33.937634] USB Universal Host Controller Interface driver v3.0
[ 33.956440] ACPI: PCI Interrupt Link [LNKD] enabled at IRQ 10
[ 33.973722] ACPI: PCI Interrupt 0000:00:07.2[D] -> Link [LNKD] -> GSI 10
(level, low) -> IRQ 10
[ 34.000036] uhci_hcd 0000:00:07.2: UHCI Host Controller
[ 34.015855] drivers/usb/core/inode.c: creating file 'devices'
[ 34.033135] drivers/usb/core/inode.c: creating file '001'
[ 34.049370] uhci_hcd 0000:00:07.2: new USB bus registered, assigned bus
number 1
[ 34.071576] uhci_hcd 0000:00:07.2: detected 2 ports
[ 34.086247] uhci_hcd 0000:00:07.2: uhci_check_and_reset_hc: cmd = 0x0000
[ 34.106383] uhci_hcd 0000:00:07.2: Performing full reset
[ 34.122381] uhci_hcd 0000:00:07.2: irq 10, io base 0x0000d400
[ 34.139755] usb usb1: default language 0x0409
[ 34.152864] usb usb1: new device found, idVendor=0000, idProduct=0000
[ 34.172213] usb usb1: new device strings: Mfr=3, Product=2,
SerialNumber=1
[ 34.192864] usb usb1: Product: UHCI Host Controller
[ 34.207542] usb usb1: Manufacturer: Linux 2.6.20-rc3-mm1 uhci_hcd
[ 34.225850] usb usb1: SerialNumber: 0000:00:07.2
[ 34.239776] usb usb1: uevent
[ 34.249063] usb usb1: usb_probe_device
[ 34.260535] usb usb1: configuration #1 chosen from 1 choice
[ 34.277305] usb usb1: adding 1-0:1.0 (config #1, interface 0)
[ 34.294598] usb 1-0:1.0: uevent
[ 34.304139] hub 1-0:1.0: usb_probe_interface
[ 34.317006] hub 1-0:1.0: usb_probe_interface - got id
[ 34.332180] hub 1-0:1.0: USB hub found
[ 34.343481] hub 1-0:1.0: 2 ports detected
[ 34.355550] hub 1-0:1.0: standalone hub
[ 34.367104] hub 1-0:1.0: no power switching (usb 1.0)
[ 34.382291] hub 1-0:1.0: individual port over-current protection
[ 34.400331] hub 1-0:1.0: power on to power good time: 2ms
[ 34.416564] hub 1-0:1.0: local power source is good
[ 34.431244] hub 1-0:1.0: trying to enable port power on non-switchable
hub
[ 34.556912] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000
[ 34.573502] drivers/usb/core/inode.c: creating file '001'
[ 34.589802] ACPI: PCI Interrupt 0000:00:07.3[D] -> Link [LNKD] -> GSI 10
(level, low) -> IRQ 10
[ 34.616094] uhci_hcd 0000:00:07.3: UHCI Host Controller
[ 34.631847] uhci_hcd 0000:00:07.2: port 1 portsc 018a,00
[ 34.647841] hub 1-0:1.0: port 1, status 0300, change 0003, 1.5 Mb/s
[ 34.666699] drivers/usb/core/inode.c: creating file '002'
[ 34.682944] uhci_hcd 0000:00:07.3: new USB bus registered, assigned bus
number 2
[ 34.705169] uhci_hcd 0000:00:07.3: detected 2 ports
[ 34.719838] uhci_hcd 0000:00:07.3: uhci_check_and_reset_hc: cmd = 0x0000
[ 34.739963] uhci_hcd 0000:00:07.3: Performing full reset
[ 34.755927] uhci_hcd 0000:00:07.3: irq 10, io base 0x0000d800
[ 34.773289] usb usb2: default language 0x0409
[ 34.786405] usb usb2: new device found, idVendor=0000, idProduct=0000
[ 34.805748] usb usb2: new device strings: Mfr=3, Product=2,
SerialNumber=1
[ 34.826401] usb usb2: Product: UHCI Host Controller
[ 34.841077] usb usb2: Manufacturer: Linux 2.6.20-rc3-mm1 uhci_hcd
[ 34.859383] usb usb2: SerialNumber: 0000:00:07.3
[ 34.873284] usb usb2: uevent
[ 34.882575] usb usb2: usb_probe_device
[ 34.893988] usb usb2: configuration #1 chosen from 1 choice
[ 34.910742] usb usb2: adding 2-0:1.0 (config #1, interface 0)
[ 34.928037] usb 2-0:1.0: uevent
[ 34.937570] hub 2-0:1.0: usb_probe_interface
[ 34.950416] hub 2-0:1.0: usb_probe_interface - got id
[ 34.965587] hub 2-0:1.0: USB hub found
[ 34.976891] hub 2-0:1.0: 2 ports detected
[ 34.988967] hub 2-0:1.0: standalone hub
[ 35.000525] hub 2-0:1.0: no power switching (usb 1.0)
[ 35.015698] hub 2-0:1.0: individual port over-current protection
[ 35.033734] hub 2-0:1.0: power on to power good time: 2ms
[ 35.049983] hub 2-0:1.0: local power source is good
[ 35.064640] hub 2-0:1.0: trying to enable port power on non-switchable
hub
[ 35.116494] hub 1-0:1.0: debounce: port 1: total 100ms stable 100ms
status 0x300
[ 35.138708] uhci_hcd 0000:00:07.2: port 2 portsc 018a,00
[ 35.154666] hub 1-0:1.0: port 2, status 0300, change 0003, 1.5 Mb/s
[ 35.206599] drivers/usb/core/inode.c: creating file '001'
[ 35.326357] hub 1-0:1.0: debounce: port 2: total 100ms stable 100ms
status 0x300
[ 35.348562] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000
[ 35.365059] hub 2-0:1.0: state 7 ports 2 chg 0000 evt 0006
[ 35.381562] uhci_hcd 0000:00:07.3: port 1 portsc 018a,00
[ 35.397545] hub 2-0:1.0: port 1, status 0300, change 0003, 1.5 Mb/s
[ 35.576194] hub 2-0:1.0: debounce: port 1: total 100ms stable 100ms
status 0x300
[ 35.598396] uhci_hcd 0000:00:07.3: port 2 portsc 018a,00
[ 35.614379] hub 2-0:1.0: port 2, status 0300, change 0003, 1.5 Mb/s
[ 35.786058] hub 2-0:1.0: debounce: port 2: total 100ms stable 100ms
status 0x300
[ 35.808274] hub 2-0:1.0: state 7 ports 2 chg 0000 evt 0000
[ 35.824778] usbcore: registered new interface driver libusual
[ 35.842057] pnp: the driver 'i8042 kbd' has been registered
[ 35.858917] pnp: match found with the PnP device '00:0c' and the
driver 'i8042 kbd'
[ 35.881912] pnp: the driver 'i8042 aux' has been registered
[ 35.898733] pnp: match found with the PnP device '00:0b' and the
driver 'i8042 aux'
[ 35.921737] PNP: PS/2 Controller [PNP0303:PS2K,PNP0f13:PS2M] at
0x60,0x64 irq 1,12
[ 35.945350] serio: i8042 KBD port at 0x60,0x64 irq 1
[ 35.960290] serio: i8042 AUX port at 0x60,0x64 irq 12
[ 35.975850] mice: PS/2 mouse device common for all mice
[ 36.010751] input: AT Translated Set 2 keyboard as /class/input/input1
[ 36.034199] input: PC Speaker as /class/input/input2
[ 36.186876] input: GenPS/2 Genius Mouse as /class/input/input3
[ 36.206971] i2c /dev entries driver
[ 36.445627] usb usb1: suspend_rh (auto-stop)
[ 36.458476] PM-Timer running at invalid rate: 142% of normal - aborting.
[ 36.478648] Advanced Linux Sound Architecture Driver Version 1.0.14rc1
(Wed Dec 20 08:11:48 2006 UTC).
[ 36.507819] ACPI: PCI Interrupt 0000:00:09.1[A] -> Link [LNKB] -> GSI 10
(level, low) -> IRQ 10
[ 36.537183] ACPI: PCI Interrupt Link [LNKC] enabled at IRQ 5
[ 36.554233] PCI: setting IRQ 5 as level-triggered
[ 36.568388] ACPI: PCI Interrupt 0000:00:07.5[C] -> Link [LNKC] -> GSI 5
(level, low) -> IRQ 5
[ 36.594308] PCI: Setting latency timer of device 0000:00:07.5 to 64
[ 36.935312] usb usb2: suspend_rh (auto-stop)
[ 37.127203] ALSA device list:
[ 37.136168] #0: VIA 82C686A/B rev20 with STAC9721,23 at 0xdc00, irq 5
[ 37.156033] #1: Brooktree Bt878 at 0xdf002000, irq 10
[ 37.171882] NET: Registered protocol family 1
[ 37.185100] Testing NMI watchdog ... OK.
[ 37.297665] Using IPI Shortcut mode
[ 37.308285] ACPI: (supports<6>Time: tsc clocksource has been installed.
[ 37.328255] Clock event device lapic disabled
[ 37.341366] Clock event device pit configured with caps set: 08
[ 37.359174] Switched to high resolution mode on CPU 0
[ 37.374369] Time: pit clocksource has been installed.
[ 37.394488] S0 S1 S4 S5)
[ 37.414706] XFS mounting filesystem sdb6
[ 37.567380] Ending clean XFS mount for filesystem: sdb6
[ 37.583482] VFS: Mounted root (xfs filesystem) readonly.
[ 8.380000] Freeing unused kernel memory: 204k freed
[ 6575.070000] BUG: NMI Watchdog detected LOCKUP on CPU0, eip c0109cde,
registers:
[ 6575.070000] Modules linked in:
[ 6575.070000] CPU: 0
[ 6575.070000] EIP: 0060:[<c0109cde>] Not tainted VLI
[ 6575.070000] EFLAGS: 00000046 (2.6.20-rc3-mm1 #4)
[ 6575.070000] EIP is at pit_read+0x1e/0xa0
[ 6575.070000] eax: 00000079 ebx: 0004fb1c ecx: 00000000 edx:
00000082
[ 6575.070000] esi: 00099333 edi: e121b846 ebp: 0004fb1c esp:
c0575ec0
[ 6575.070000] ds: 007b es: 007b fs: 00d8 gs: 0000 ss: 0068
[ 6575.070000] Process swapper (pid: 0, ti=c0574000 task=c0527480
task.ti=c0574000)
[ 6575.070000] Stack: 0004fb1c c0575ef0 c01244c1 c0575ef0 0004fb1c c0575ef0
e121b846 000005fa
[ 6575.070000] c0133081 00000000 c0575f24 c01330c6 45a2ac72 0a92f42e
c052f130 80a5e194
[ 6575.070000] c0133947 00000000 e17def7a 000005fa e121b846 000005fa
c052f0e4 00000000
[ 6575.070000] Call Trace:
[ 6575.070000] [<c01244c1>] getnstimeofday+0x31/0xc0
[ 6575.070000] [<c0133081>] ktime_get_ts+0x11/0x40
[ 6575.070000] [<c01330c6>] ktime_get+0x16/0x40
[ 6575.070000] [<c0133947>] hrtimer_interrupt+0x37/0x1e0
[ 6575.070000] [<c010744f>] timer_interrupt+0x2f/0x40
[ 6575.070000] [<c0143c60>] handle_IRQ_event+0x20/0x50
[ 6575.070000] [<c0145391>] handle_level_irq+0x81/0x110
[ 6575.070000] [<c01067f6>] do_IRQ+0x46/0x80
[ 6575.070000] [<c0104a96>] common_interrupt+0x2e/0x34
[ 6575.070000] [<c0136080>] handle_noop+0x0/0x10
[ 6575.070000] [<c028aecf>] acpi_processor_idle+0x1db/0x384
[ 6575.070000] [<c028acf4>] acpi_processor_idle+0x0/0x384
[ 6575.070000] [<c0102469>] cpu_idle+0x49/0x80
[ 6575.070000] [<c0576b85>] start_kernel+0x2d5/0x380
[ 6575.070000] [<c05764b0>] unknown_bootoption+0x0/0x260
[ 6575.070000] =======================
[ 6575.070000] Code: e0 b7 52 c0 e9 34 66 31 00 8d 74 26 00 56 b8 e0 b7 52
c0 53 e8 34 65 31 00 8b 35 20 e0 52 c0 89 c2 31 c0 e6 43 e6 80 e4 40 e6 80
<0f> b6 d8 e4 40 e6 80 0f b6 c0 c1 e0 08 09 c3 8
[ 6575.070000] [ 6575.070000]
Capslock and Scrolllock are blinking again, Sys+RQ still works.
After a soft-reboot the NMI trace changed to:
[ 28.964111] XFS mounting filesystem sdb6
[ 34.856030] BUG: NMI Watchdog detected LOCKUP on CPU0, eip c0109cdc,
registers:
[ 34.878060] Modules linked in:
[ 34.887340] CPU: 0
[ 34.887342] EIP: 0060:[<c0109cdc>] Not tainted VLI
[ 34.887344] EFLAGS: 00000046 (2.6.20-rc3-mm1 #4)
[ 34.924555] EIP is at pit_read+0x1c/0xa0
[ 34.936356] eax: 000000a9 ebx: 0005083a ecx: 00000000 edx:
00000086
[ 34.956723] esi: 00092abe edi: 9e741e83 ebp: 0005083a esp:
dff83a08
[ 34.977091] ds: 007b es: 007b fs: 00d8 gs: 0000 ss: 0068
[ 34.994600] Process swapper (pid: 1, ti=dff82000 task=dff81510
task.ti=dff82000)
[ 35.016264] Stack: 0005083a dff83a38 c01244c1 dff83a38 0005083a dff83a38
9e741e83 000005bc
[ 35.042007] c0133081 00000000 dff83a6c c01330c6 45a2ac47 2d801ce0
c052f130 80a5e194
[ 35.067726] c0133947 00000000 9e9d366d 000005bc 9e741e83 000005bc
c052f0e4 00000000
[ 35.093445] Call Trace:
[ 35.101424] [<c01244c1>] getnstimeofday+0x31/0xc0
[ 35.115917] [<c0133081>] ktime_get_ts+0x11/0x40
[ 35.129869] [<c01330c6>] ktime_get+0x16/0x40
[ 35.143039] [<c0133947>] hrtimer_interrupt+0x37/0x1e0
[ 35.158550] [<c010744f>] timer_interrupt+0x2f/0x40
[ 35.173304] [<c0143c60>] handle_IRQ_event+0x20/0x50
[ 35.188294] [<c0145391>] handle_level_irq+0x81/0x110
[ 35.203542] [<c01067f6>] do_IRQ+0x46/0x80
[ 35.215933] [<c011c4b1>] vprintk+0x201/0x2f0
[ 35.229107] [<c0104a96>] common_interrupt+0x2e/0x34
[ 35.244096] [<c023a88d>] cmn_err+0x9d/0xb0
[ 35.256747] [<c0420337>] _spin_unlock_irqrestore+0x47/0x60
[ 35.273555] [<c023a88d>] cmn_err+0x9d/0xb0
[ 35.286207] [<c0218218>] xfs_log_mount+0x48/0x5d0
[ 35.300677] [<c021fbbd>] xfs_mountfs+0xb1d/0xfa0
[ 35.314886] [<c041fe89>] _spin_lock+0x29/0x40
[ 35.328316] [<c0231e93>] xfs_setsize_buftarg_flags+0x33/0xc0
[ 35.345645] [<c0227391>] xfs_mount+0x641/0x9c0
[ 35.359337] [<c0226d50>] xfs_mount+0x0/0x9c0
[ 35.372507] [<c0239e92>] vfs_mount+0x22/0x30
[ 35.385677] [<c0239cb8>] xfs_fs_fill_super+0x78/0x1e0
[ 35.401187] [<c025cf8f>] snprintf+0x1f/0x30
[ 35.414098] [<c01a2222>] disk_name+0x92/0xc0
[ 35.427269] [<c0169bd4>] get_sb_bdev+0x104/0x140
[ 35.441479] [<c0238ed0>] xfs_fs_get_sb+0x20/0x30
[ 35.455690] [<c0239c40>] xfs_fs_fill_super+0x0/0x1e0
[ 35.470938] [<c0169696>] vfs_kern_mount+0xb6/0x130
[ 35.486473] [<c0169769>] do_kern_mount+0x39/0x60
[ 35.500684] [<c017ec5c>] do_mount+0x42c/0x700
[ 35.514114] [<c041fdb4>] _spin_unlock+0x14/0x20
[ 35.528065] [<c0258646>] _atomic_dec_and_lock+0x16/0x60
[ 35.544094] [<c014bdb1>] get_page_from_freelist+0x1e1/0x380
[ 35.561162] [<c014c27a>] __get_free_pages+0x1a/0x40
[ 35.576150] [<c017d4d0>] copy_mount_options+0x40/0x150
[ 35.591920] [<c017efa2>] sys_mount+0x72/0xb0
[ 35.605090] [<c0576e9e>] mount_block_root+0x8e/0x270
[ 35.620340] [<c0171d57>] sys_mknod+0x27/0x30
[ 35.633511] [<c05770d0>] mount_root+0x50/0x90
[ 35.646942] [<c0577222>] prepare_namespace+0x112/0x150
[ 35.662710] [<c016658f>] sys_access+0x1f/0x30
[ 35.676142] [<c0576842>] init+0x132/0x1a0
[ 35.688533] [<c0576710>] init+0x0/0x1a0
[ 35.700406] [<c0576710>] init+0x0/0x1a0
[ 35.712251] [<c0104c2f>] kernel_thread_helper+0x7/0x18
Next try: hang without the NMI triggering:
[ 37.253929] XFS mounting filesystem sdb6
[ 37.398376] Ending clean XFS mount for filesystem: sdb6
[ 37.414462] VFS: Mounted root (xfs filesystem) readonly.
[ 8.390000] Freeing unused kernel memory: 204k freed
-> Hangs here
Part of SysRQ-T:
[ 8.880000]
[ 8.880000] free sibling
[ 8.880000] task PC stack pid father child younger
older
[ 8.880000] init D DFD0D028 0 1 0 2
(NOTLB)
[ 8.880000] dff83d28 00000082 c170b438 dfd0d028 00000046 00000000
00000002 00000001
[ 8.880000] 0000000a dff81510 114a0c00 00000002 00000000 dff8161c
c04201c0 dfd5af04
[ 8.880000] c024ec06 00000001 c13f8ea0 dff83d64 dff83d34 c041dd52
dff83d5c c1401110
[ 8.880000] Call Trace:
[ 8.880000] [<c04201c0>] _spin_unlock_irq+0x20/0x30
[ 8.880000] [<c024ec06>] blk_unplug_current+0xc6/0xe0
[ 8.880000] [<c041dd52>] io_schedule+0x42/0x60
[ 8.880000] [<c01470f5>] sleep_on_page+0x5/0x10
[ 8.880000] [<c041dfcc>] __wait_on_bit_lock+0x3c/0x70
[ 8.880000] [<c01470f0>] sleep_on_page+0x0/0x10
[ 8.880000] [<c01470e3>] __lock_page+0x73/0x80
[ 8.880000] [<c012fb20>] wake_bit_function+0x0/0x60
[ 8.880000] [<c014798c>] do_generic_mapping_read+0x26c/0x590
[ 8.880000] [<c0149c8d>] generic_file_aio_read+0xfd/0x220
[ 8.880000] [<c0146df0>] file_read_actor+0x0/0x140
[ 8.880000] [<c02381c3>] xfs_read+0x1c3/0x340
[ 8.880000] [<c023480c>] xfs_file_aio_read+0x6c/0x80
[ 8.880000] [<c0167475>] do_sync_read+0xd5/0x120
[ 8.880000] [<c012fad0>] autoremove_wake_function+0x0/0x50
[ 8.880000] [<c01659ae>] fd_install+0x1e/0x40
[ 8.880000] [<c0167e0c>] vfs_read+0xbc/0x180
[ 8.880000] [<c01673a0>] do_sync_read+0x0/0x120
[ 8.880000] [<c0168271>] sys_read+0x41/0x70
[ 8.880000] [<c01040ac>] syscall_call+0x7/0xb
[ 8.880000] =======================
[ 8.880000] xfsbufd S FFFF8E78 0 887 5 888
842 (L-TLB)
[ 8.880000] c17e3f70 00000086 c17e3f60 ffff8e78 c042023f 00000000
00000046 c05d6cc0
[ 8.880000] 00000009 c17deb00 abd85bd2 00000008 00000d05 c17dec0c
c01252f4 00000000
[ 8.880000] 00000282 c17e3f80 ffff8e78 dfd940d0 dfd940a0 c041deda
c041d352 00000000
[ 8.880000] Call Trace:
[ 8.880000] [<c042023f>] _spin_lock_irqsave+0x3f/0x50
[ 8.880000] [<c01252f4>] __mod_timer+0x84/0xa0
[ 8.880000] [<c041deda>] schedule_timeout+0x4a/0xc0
[ 8.880000] [<c041d352>] __sched_text_start+0x2e2/0x670
[ 8.880000] [<c0124960>] process_timeout+0x0/0x10
[ 8.880000] [<c0233aa5>] xfsbufd+0x65/0x1b0
[ 8.880000] [<c0233a40>] xfsbufd+0x0/0x1b0
[ 8.880000] [<c012f908>] kthread+0xa8/0xe0
[ 8.880000] [<c012f860>] kthread+0x0/0xe0
[ 8.880000] [<c0104c2f>] kernel_thread_helper+0x7/0x18
[ 8.880000] =======================
[ 8.880000] xfssyncd S FFFF99CF 0 888 5
887 (L-TLB)
[ 8.880000] dfdddf68 00000082 dfdddf58 ffff99cf c042023f 00000000
b610b3ad 00000008
[ 8.880000] 00000009 dff16090 b610c307 00000008 00001043 dff1619c
0000067b 00000000
[ 8.880000] 00000292 dfdddf78 ffff99cf c16bc3c0 00000bb8 c041deda
c04201c0 c0527200
[ 8.880000] Call Trace:
[ 8.880000] [<c042023f>] _spin_lock_irqsave+0x3f/0x50
[ 8.880000] [<c041deda>] schedule_timeout+0x4a/0xc0
[ 8.880000] [<c04201c0>] _spin_unlock_irq+0x20/0x30
[ 8.880000] [<c0124960>] process_timeout+0x0/0x10
[ 8.880000] [<c023967d>] xfssyncd+0x4d/0x180
[ 8.880000] [<c0239630>] xfssyncd+0x0/0x180
[ 8.880000] [<c012f908>] kthread+0xa8/0xe0
[ 8.880000] [<c012f860>] kthread+0x0/0xe0
[ 8.880000] [<c0104c2f>] kernel_thread_helper+0x7/0x18
[ 8.880000] =======================
[ 8.880000] hotplug D 00000046 0 890 4 891
(NOTLB)
[ 8.880000] c162dd28 00000082 00000246 00000046 c140112c c162dd64
00000002 00000046
[ 8.880000] 0000000a dfe18ae0 114a0c00 00000002 00000000 dfe18bec
c042023f 00000000
[ 8.880000] 00000002 00000001 c13f8ea0 c162dd64 c162dd34 c041dd52
c162dd5c c1401110
[ 8.880000] Call Trace:
[ 8.880000] [<c042023f>] _spin_lock_irqsave+0x3f/0x50
[ 8.880000] [<c041dd52>] io_schedule+0x42/0x60
[ 8.880000] [<c01470f5>] sleep_on_page+0x5/0x10
[ 8.880000] [<c041dfcc>] __wait_on_bit_lock+0x3c/0x70
[ 8.880000] [<c01470f0>] sleep_on_page+0x0/0x10
[ 8.880000] [<c01470e3>] __lock_page+0x73/0x80
[ 8.880000] [<c012fb20>] wake_bit_function+0x0/0x60
[ 8.880000] [<c014798c>] do_generic_mapping_read+0x26c/0x590
[ 8.880000] [<c02372f0>] xfs_vn_follow_link+0x0/0x100
[ 8.880000] [<c0149c8d>] generic_file_aio_read+0xfd/0x220
[ 8.880000] [<c0146df0>] file_read_actor+0x0/0x140
[ 8.880000] [<c02381c3>] xfs_read+0x1c3/0x340
[ 8.880000] [<c023480c>] xfs_file_aio_read+0x6c/0x80
[ 8.880000] [<c0167475>] do_sync_read+0xd5/0x120
[ 8.880000] [<c012fad0>] autoremove_wake_function+0x0/0x50
[ 8.880000] [<c01659ae>] fd_install+0x1e/0x40
[ 8.880000] [<c0167e0c>] vfs_read+0xbc/0x180
[ 8.880000] [<c01673a0>] do_sync_read+0x0/0x120
[ 8.880000] [<c0168271>] sys_read+0x41/0x70
[ 8.880000] [<c01040ac>] syscall_call+0x7/0xb
[ 8.880000] =======================
[ 8.880000] hotplug D 00000046 0 891 4
890 (NOTLB)
[ 8.880000] c162fd28 00000082 00000246 00000046 c140112c c162fd64
00000002 00000046
[ 8.880000] 00000009 dfe18070 114a0c00 00000002 00000000 dfe1817c
c042023f 00000000
[ 8.880000] 00000002 00000001 c13f8ea0 c162fd64 c162fd34 c041dd52
c162fd5c c1401110
[ 8.880000] Call Trace:
[ 8.880000] [<c042023f>] _spin_lock_irqsave+0x3f/0x50
[ 8.880000] [<c041dd52>] io_schedule+0x42/0x60
[ 8.880000] [<c01470f5>] sleep_on_page+0x5/0x10
[ 8.880000] [<c041dfcc>] __wait_on_bit_lock+0x3c/0x70
[ 8.880000] [<c01470f0>] sleep_on_page+0x0/0x10
[ 8.880000] [<c01470e3>] __lock_page+0x73/0x80
[ 8.880000] [<c012fb20>] wake_bit_function+0x0/0x60
[ 8.880000] [<c014798c>] do_generic_mapping_read+0x26c/0x590
[ 8.880000] [<c02372f0>] xfs_vn_follow_link+0x0/0x100
[ 8.880000] [<c0149c8d>] generic_file_aio_read+0xfd/0x220
[ 8.880000] [<c0146df0>] file_read_actor+0x0/0x140
[ 8.880000] [<c02381c3>] xfs_read+0x1c3/0x340
[ 8.880000] [<c023480c>] xfs_file_aio_read+0x6c/0x80
[ 8.880000] [<c0167475>] do_sync_read+0xd5/0x120
[ 8.880000] [<c012fad0>] autoremove_wake_function+0x0/0x50
[ 8.880000] [<c01659ae>] fd_install+0x1e/0x40
[ 8.880000] [<c0167e0c>] vfs_read+0xbc/0x180
[ 8.880000] [<c01673a0>] do_sync_read+0x0/0x120
[ 8.880000] [<c0168271>] sys_read+0x41/0x70
[ 8.880000] [<c01040ac>] syscall_call+0x7/0xb
[ 8.880000] =======================
[ 8.880000]
[ 8.880000] Showing all locks held in the system:
[ 8.880000]
[ 8.880000] =============================================
[ 8.880000]
A try without rootfsflags=nobarrier:
Same hang:
[ 36.070931] XFS mounting filesystem sdb6
[ 36.207102] Ending clean XFS mount for filesystem: sdb6
[ 36.223176] VFS: Mounted root (xfs filesystem) readonly.
[ 8.750000] Freeing unused kernel memory: 204k freed
SysRq+T: Again no locks held, but init hangs this time at:
[ 9.440000] free sibling
[ 9.440000] task PC stack pid father child younger
older
[ 9.440000] init D 00000046 0 1 0 2
(NOTLB)
[ 9.440000] dff83e94 00000086 dff81510 00000046 c1400eec dff83ed0
00000002 00000046
[ 9.440000] 0000000a dff81510 32aaf800 00000002 00000000 dff8161c
c042023f 00000000
[ 9.440000] 00000002 00000000 dfcf3790 dff83ed0 dff83ea0 c041dd52
dff83ec8 c1400ed0
[ 9.440000] Call Trace:
[ 9.440000] [<c042023f>] _spin_lock_irqsave+0x3f/0x50
[ 9.440000] [<c041dd52>] io_schedule+0x42/0x60
[ 9.440000] [<c01470f5>] sleep_on_page+0x5/0x10
[ 9.440000] [<c041dfcc>] __wait_on_bit_lock+0x3c/0x70
[ 9.440000] [<c01470f0>] sleep_on_page+0x0/0x10
[ 9.440000] [<c01470e3>] __lock_page+0x73/0x80
[ 9.440000] [<c012fb20>] wake_bit_function+0x0/0x60
[ 9.440000] [<c0149a65>] filemap_nopage+0x2f5/0x420
[ 9.440000] [<c01545f1>] __handle_mm_fault+0x111/0x8b0
[ 9.440000] [<c0115dc9>] do_page_fault+0xb9/0x610
[ 9.440000] [<c0115e36>] do_page_fault+0x126/0x610
[ 9.440000] [<c0115d10>] do_page_fault+0x0/0x610
[ 9.440000] [<c0420424>] error_code+0x74/0x7c
[ 9.440000] =======================
xfsbufd, xfssyncd and two hotplugs in D-state all hang at
_spin_lock_irqsave+0x3f/0x50
Last try: Also removing lapic from the commandline...
Same hang after Freeing unused kernel memory, but now not even SysRQ
works...
Anything else I should/can try?
Torsten
On Mon, Jan 08 2007, Torsten Kaiser wrote:
> On Monday 08 January 2007 09:52, Jens Axboe wrote:
> > --- a/block/ll_rw_blk.c
> > +++ b/block/ll_rw_blk.c
> > @@ -1542,7 +1542,7 @@ static inline void
> > - blk_unplug_current();
> > + blk_replug_current_nested();
>
> Does not help. Dmesg follows:
[snip]
Strange, it works perfectly for me now. Not using -mm though, but the
plug branch. And it did hang before. Fengguang, any change for you?
--
Jens Axboe
On Tue, Jan 09, 2007 at 10:19:00AM +0100, Jens Axboe wrote:
> On Mon, Jan 08 2007, Torsten Kaiser wrote:
> > On Monday 08 January 2007 09:52, Jens Axboe wrote:
> > > --- a/block/ll_rw_blk.c
> > > +++ b/block/ll_rw_blk.c
> > > @@ -1542,7 +1542,7 @@ static inline void
> > > - blk_unplug_current();
> > > + blk_replug_current_nested();
> >
> > Does not help. Dmesg follows:
>
> [snip]
>
> Strange, it works perfectly for me now. Not using -mm though, but the
> plug branch. And it did hang before. Fengguang, any change for you?
2.6.20-rc3-mm1 plus your patch works for me.
Lucky enough to found this before giving up:
mount takes 39s, and umount takes 42s.
Jan 9 19:37:51 localhost kernel: [ 478.217846] kjournald starting. Commit interval 5 seconds
Jan 9 19:38:30 localhost kernel: [ 517.120984] EXT3 FS on md2, internal journal
Jan 9 19:38:30 localhost kernel: [ 517.121052] EXT3-fs: mounted filesystem with ordered data mode.
Under KDE, it fails to respond from time to time, some processes
randomly get stucked:
USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
root 5702 0.0 0.0 0 0 ? D< 19:40 0:00 [kjournald]
wfg 6115 0.0 1.3 149724 27264 tty1 D 19:44 0:00 amarokapp
wfg 6150 0.0 0.0 15524 1640 ? D 19:50 0:00 /usr/bin/fetchmail -a
The initial mount calltrace is:
Jan 9 19:33:11 localhost kernel: [ 198.323105] mount D 00000025899a9f02 5144 5566 5552 (NOTLB)
Jan 9 19:33:11 localhost kernel: [ 198.323305] ffff810079f298c8 0000000000000046 0000000000000000 0000000000000286
Jan 9 19:33:11 localhost kernel: [ 198.323454] 0000000000000000 0000000000000286 ffff810037eeae20 0000000000000020
Jan 9 19:33:11 localhost kernel: [ 198.323604] 0000000000000008 ffff810079d13080 ffffffff813a74e0 0000000000001472
Jan 9 19:33:11 localhost kernel: [ 198.323717] Call Trace:
Jan 9 19:33:11 localhost kernel: [ 198.323796] [<ffffffff81061b9a>] getnstimeofday+0x3a/0xa0
Jan 9 19:33:11 localhost kernel: [ 198.323839] [<ffffffff810699d8>] io_schedule+0x98/0xd0
Jan 9 19:33:11 localhost kernel: [ 198.323881] [<ffffffff810f1789>] sleep_on_buffer+0x9/0x10
Jan 9 19:33:11 localhost kernel: [ 198.323923] [<ffffffff81069c95>] __wait_on_bit+0x45/0x80
Jan 9 19:33:11 localhost kernel: [ 198.323964] [<ffffffff810f1780>] sleep_on_buffer+0x0/0x10
Jan 9 19:33:11 localhost kernel: [ 198.324006] [<ffffffff810f1780>] sleep_on_buffer+0x0/0x10
Jan 9 19:33:11 localhost kernel: [ 198.324048] [<ffffffff81069d48>] out_of_line_wait_on_bit+0x78/0x90
Jan 9 19:33:11 localhost kernel: [ 198.324090] [<ffffffff810a25f0>] wake_bit_function+0x0/0x40
Jan 9 19:33:11 localhost kernel: [ 198.324132] [<ffffffff8104f620>] __wait_on_buffer+0x20/0x30
Jan 9 19:33:11 localhost kernel: [ 198.324174] [<ffffffff8103ecfd>] sync_dirty_buffer+0xad/0xf0
Jan 9 19:33:11 localhost kernel: [ 198.324216] [<ffffffff811196ea>] ext3_commit_super+0x6a/0x80
Jan 9 19:33:11 localhost kernel: [ 198.324258] [<ffffffff8111a066>] ext3_setup_super+0x106/0x1c0
Jan 9 19:33:11 localhost kernel: [ 198.324299] [<ffffffff8103f61e>] d_instantiate+0x9e/0xb0
Jan 9 19:33:11 localhost kernel: [ 198.324342] [<ffffffff8111c104>] ext3_fill_super+0x12f4/0x1650
Jan 9 19:33:11 localhost kernel: [ 198.324388] [<ffffffff810de8c7>] get_sb_bdev+0x117/0x180
Jan 9 19:33:11 localhost kernel: [ 198.324429] [<ffffffff8111ae10>] ext3_fill_super+0x0/0x1650
Jan 9 19:33:11 localhost kernel: [ 198.324472] [<ffffffff811194d3>] ext3_get_sb+0x13/0x20
Jan 9 19:33:11 localhost kernel: [ 198.324514] [<ffffffff810de2d0>] vfs_kern_mount+0xc0/0x160
Jan 9 19:33:11 localhost kernel: [ 198.324556] [<ffffffff810de3da>] do_kern_mount+0x4a/0x70
Jan 9 19:33:11 localhost kernel: [ 198.324599] [<ffffffff810e914e>] do_mount+0x73e/0x7c0
Jan 9 19:33:11 localhost kernel: [ 198.324641] [<ffffffff8102ff70>] mntput_no_expire+0x20/0xb0
Jan 9 19:33:11 localhost kernel: [ 198.324683] [<ffffffff8100edc8>] link_path_walk+0xf8/0x110
Jan 9 19:33:11 localhost kernel: [ 198.324726] [<ffffffff8106bdf6>] _spin_unlock+0x26/0x30
Jan 9 19:33:11 localhost kernel: [ 198.324767] [<ffffffff8101c46f>] bad_range+0x1f/0x80
Jan 9 19:33:11 localhost kernel: [ 198.324809] [<ffffffff8100a4a7>] get_page_from_freelist+0x307/0x600
Jan 9 19:33:11 localhost kernel: [ 198.324853] [<ffffffff81025cce>] __user_walk_fd+0x5e/0x80
Jan 9 19:33:11 localhost kernel: [ 198.324895] [<ffffffff8100f935>] __alloc_pages+0x75/0x320
Jan 9 19:33:11 localhost kernel: [ 198.324939] [<ffffffff81016ab9>] alloc_pages_current+0xb9/0xd0
Jan 9 19:33:11 localhost kernel: [ 198.324983] [<ffffffff81051b14>] sys_mount+0x94/0xf0
Jan 9 19:33:11 localhost kernel: [ 198.325024] [<ffffffff8106b8b1>] trace_hardirqs_on_thunk+0x35/0x37
Jan 9 19:33:11 localhost kernel: [ 198.325068] [<ffffffff8106511e>] system_call+0x7e/0x83
And here is the processes being blocked:
Jan 9 19:52:58 localhost kernel: [ 1384.882119] spamassassin D 0000013ca8ba4528 3992 6171 6170 (NOTLB)
Jan 9 19:52:58 localhost kernel: [ 1384.882125] ffff81005c42fdd8 0000000000000046 0000000000000000 0000000200000001
Jan 9 19:52:58 localhost kernel: [ 1384.882128] 0000000000000000 ffff81007b49a988 ffff810073a4d630 0000000000000046
Jan 9 19:52:58 localhost kernel: [ 1384.882131] 0000000000000009 ffff81005c41a0c0 ffffffff813a74e0 0000000000000dc1
Jan 9 19:52:58 localhost kernel: [ 1384.882134] Call Trace:
Jan 9 19:52:58 localhost kernel: [ 1384.882141] [<ffffffff81127b55>] log_wait_commit+0xe5/0x140
Jan 9 19:52:58 localhost kernel: [ 1384.882143] [<ffffffff810a25b0>] autoremove_wake_function+0x0/0x40
Jan 9 19:52:58 localhost kernel: [ 1384.882147] [<ffffffff81121b78>] journal_stop+0x1f8/0x230
Jan 9 19:52:58 localhost kernel: [ 1384.882151] [<ffffffff81122874>] journal_force_commit+0x24/0x30
Jan 9 19:52:58 localhost kernel: [ 1384.882153] [<ffffffff8111a586>] ext3_force_commit+0x26/0x30
Jan 9 19:52:58 localhost kernel: [ 1384.882156] [<ffffffff8111036b>] ext3_sync_file+0x9b/0xe0
Jan 9 19:52:58 localhost kernel: [ 1384.882158] [<ffffffff8106a5e5>] mutex_lock+0x25/0x30
Jan 9 19:52:58 localhost kernel: [ 1384.882161] [<ffffffff81055844>] do_fsync+0x64/0xe0
Jan 9 19:52:58 localhost kernel: [ 1384.882164] [<ffffffff810f0f91>] __do_fsync+0x31/0x50
Jan 9 19:52:58 localhost kernel: [ 1384.882167] [<ffffffff810f0fbe>] sys_fdatasync+0xe/0x10
Jan 9 19:52:58 localhost kernel: [ 1384.882169] [<ffffffff8106511e>] system_call+0x7e/0x83
Jan 9 19:57:27 localhost kernel: [ 1653.082457] amarokapp D 00000173cc57562b 4776 6248 1 6259 6242 (NOTLB)
Jan 9 19:57:27 localhost kernel: [ 1653.082463] ffff8100549bddd8 0000000000000046 0000000000000000 0000000200000001
Jan 9 19:57:27 localhost kernel: [ 1653.082466] 0000000000000000 ffff81007b49a988 ffff810073a4d708 0000000000000046
Jan 9 19:57:27 localhost kernel: [ 1653.082470] 0000000000000009 ffff8100549ba0c0 ffff81006175e0c0 0000000000000e03
Jan 9 19:57:27 localhost kernel: [ 1653.082473] Call Trace:
Jan 9 19:57:27 localhost kernel: [ 1653.082479] [<ffffffff81127b55>] log_wait_commit+0xe5/0x140
Jan 9 19:57:27 localhost kernel: [ 1653.082482] [<ffffffff810a25b0>] autoremove_wake_function+0x0/0x40
Jan 9 19:57:27 localhost kernel: [ 1653.082486] [<ffffffff81121b78>] journal_stop+0x1f8/0x230
Jan 9 19:57:27 localhost kernel: [ 1653.082490] [<ffffffff81122874>] journal_force_commit+0x24/0x30
Jan 9 19:57:27 localhost kernel: [ 1653.082492] [<ffffffff8111a586>] ext3_force_commit+0x26/0x30
Jan 9 19:57:27 localhost kernel: [ 1653.082494] [<ffffffff8111036b>] ext3_sync_file+0x9b/0xe0
Jan 9 19:57:27 localhost kernel: [ 1653.082497] [<ffffffff8106a5e5>] mutex_lock+0x25/0x30
Jan 9 19:57:27 localhost kernel: [ 1653.082499] [<ffffffff81055844>] do_fsync+0x64/0xe0
Jan 9 19:57:27 localhost kernel: [ 1653.082503] [<ffffffff810f0f91>] __do_fsync+0x31/0x50
Jan 9 19:57:27 localhost kernel: [ 1653.082505] [<ffffffff810f0fcb>] sys_fsync+0xb/0x10
Jan 9 19:57:27 localhost kernel: [ 1653.082507] [<ffffffff8106511e>] system_call+0x7e/0x83
Regards,
Wu
On Tue, Jan 09 2007, Fengguang Wu wrote:
> On Tue, Jan 09, 2007 at 10:19:00AM +0100, Jens Axboe wrote:
> > On Mon, Jan 08 2007, Torsten Kaiser wrote:
> > > On Monday 08 January 2007 09:52, Jens Axboe wrote:
> > > > --- a/block/ll_rw_blk.c
> > > > +++ b/block/ll_rw_blk.c
> > > > @@ -1542,7 +1542,7 @@ static inline void
> > > > - blk_unplug_current();
> > > > + blk_replug_current_nested();
> > >
> > > Does not help. Dmesg follows:
> >
> > [snip]
> >
> > Strange, it works perfectly for me now. Not using -mm though, but the
> > plug branch. And it did hang before. Fengguang, any change for you?
>
> 2.6.20-rc3-mm1 plus your patch works for me.
>
> Lucky enough to found this before giving up:
>
> mount takes 39s, and umount takes 42s.
Do the finish quicker, if you cat /proc/mdstat after issuing the mount
or umount? I'm testing md right now and I'm seeing a few oddities wrt
that, looking further...
You probably also want this, at least if you ever shut down your arrays.
diff --git a/block/ll_rw_blk.c b/block/ll_rw_blk.c
index 4c8ac7e..34b7936 100644
--- a/block/ll_rw_blk.c
+++ b/block/ll_rw_blk.c
@@ -1745,6 +1745,11 @@ request_queue_t *blk_alloc_queue_node(gf
memset(q, 0, sizeof(*q));
+ if (init_qrcu_struct(&q->qrcu)) {
+ kmem_cache_free(requestq_cachep, q);
+ return NULL;
+ }
+
snprintf(q->kobj.name, KOBJ_NAME_LEN, "%s", "queue");
q->kobj.ktype = &queue_ktype;
kobject_init(&q->kobj);
@@ -1802,11 +1807,6 @@ blk_init_queue_node(request_fn_proc *rfn
if (!q)
return NULL;
- if (init_qrcu_struct(&q->qrcu)) {
- kmem_cache_free(requestq_cachep, q);
- return NULL;
- }
-
q->node = node_id;
if (blk_init_free_list(q)) {
cleanup_qrcu_struct(&q->qrcu);
--
Jens Axboe