tasks hangs in D state while writing to xfs

DISCUSSION Marcin M 5 participants 10 messages Oct 15, 2011 – Oct 16, 2011

Share & tools

Marcin M

author

2011-10-15 12:00 UTC #0 lore raw

Hello!
I've noticed strange problem with xfs. I've created filesystem with blocksize=1024 and log as small as it possible. Next i'm copying files using rsync, after sometime rsync hangs in D state. So i can't kill it, i've got to reboot hosts. In dmesg i'm getting such messages:

[ 1320.535833] INFO: task flush-8:0:1173 blocked for more than 120 seconds.
[ 1320.535834] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 1320.535836] flush-8:0       D 0000000000000000     0  1173      2
0x00000000
[ 1320.535838]  ffff88001e1a0000 0000000000000046 ffff880000000000
0000000000000000
[ 1320.535841]  ffff88001ed14a40 000000000000cd80 ffff88001e1a03f0
ffffffff81030fa0
[ 1320.535843]  000000000000cd80 ffff88001e1a03f0 ffff88001e1a03f0
000000000000cd80
[ 1320.535845] Call Trace:
[ 1320.535847]  [<ffffffff81030fa0>] ? check_preempt_wakeup+0x140/0x140
[ 1320.535854]  [<ffffffffa006dd3b>] ?
xfs_bmap_search_multi_extents+0xab/0x120 [xfs]
[ 1320.535860]  [<ffffffffa006def8>] ?
xfs_bmap_search_extents+0x68/0x100 [xfs]
[ 1320.535868]  [<ffffffffa009ae2b>] ? xlog_grant_log_space+0x16b/0x340
[xfs]
[ 1320.535874]  [<ffffffffa00af6c2>] ? kmem_zone_zalloc+0x32/0x50 [xfs]
[ 1320.535876]  [<ffffffff81036ef0>] ? try_to_wake_up+0x280/0x280
[ 1320.535884]  [<ffffffffa00a83bb>] ? xfs_trans_reserve+0x9b/0x200 [xfs]
[ 1320.535891]  [<ffffffffa00a8237>] ? xfs_trans_alloc+0x97/0xb0 [xfs]
[ 1320.535898]  [<ffffffffa0097c3b>] ?
xfs_iomap_write_allocate+0x20b/0x320 [xfs]
[ 1320.535907]  [<ffffffffa00b021f>] ? xfs_map_blocks+0x18f/0x1c0 [xfs]
[ 1320.535914]  [<ffffffffa00b13fe>] ? xfs_vm_writepage+0x1ae/0x4a0 [xfs]
[ 1320.535916]  [<ffffffff8109c797>] ? __writepage+0x17/0x40
[ 1320.535918]  [<ffffffff8109ceaa>] ? write_cache_pages+0x1ca/0x400
[ 1320.535920]  [<ffffffff8109c780>] ? set_page_dirty+0x80/0x80
[ 1320.535922]  [<ffffffff8109d128>] ? generic_writepages+0x48/0x80
[ 1320.535926]  [<ffffffff81105c82>] ? writeback_single_inode+0x102/0x260
[ 1320.535928]  [<ffffffff81106056>] ? writeback_sb_inodes+0xf6/0x1a0
[ 1320.535930]  [<ffffffff81106aeb>] ? writeback_inodes_wb+0x8b/0x140
[ 1320.535932]  [<ffffffff81106e23>] ? wb_writeback+0x283/0x2f0
[ 1320.535935]  [<ffffffff81106f24>] ? wb_do_writeback+0x94/0x1e0
[ 1320.535938]  [<ffffffff810496a0>] ? run_timer_softirq+0x240/0x240
[ 1320.535940]  [<ffffffff811070f2>] ? bdi_writeback_thread+0x82/0x150
[ 1320.535942]  [<ffffffff81107070>] ? wb_do_writeback+0x1e0/0x1e0
[ 1320.535944]  [<ffffffff81107070>] ? wb_do_writeback+0x1e0/0x1e0
[ 1320.535946]  [<ffffffff8105b7d2>] ? kthread+0xa2/0xb0
[ 1320.535948]  [<ffffffff81353919>] ? kernel_thread_helper+0x9/0x20
[ 1320.535950]  [<ffffffff813522ea>] ? retint_restore_args+0x6/0xd
[ 1320.535952]  [<ffffffff8105b730>] ? kthread_worker_fn+0x140/0x140
[ 1320.535954]  [<ffffffff81353910>] ? gs_change+0x1b/0x1b

It looks it's reproducible problem on my host. Now i'm using kernel 3.0.4-hardened-r5 but this happens with older kernels too. I did echo "t" >/proc/sysrq and i got:
[...]

[ 3038.290721] xfsbufd/sda11   S ffff88001ecf6180     0  3892      2
0x00000000
[ 3038.290721]  ffff880019562880 0000000000000046 0000000003b4ceaf
ffff880000000001
[ 3038.290721]  ffff88001e33af40 000000000000cd80 ffff880019562c70
ffffffff81030fa0
[ 3038.290721]  000000000000cd80 ffff880019562c70 ffff880019562c70
000000000000cd80
[ 3038.290721] Call Trace:
[ 3038.290721]  [<ffffffff81030fa0>] ? check_preempt_wakeup+0x140/0x140
[ 3038.290721]  [<ffffffff8123b37c>] ? sd_prep_fn+0x15c/0xac0
[ 3038.290721]  [<ffffffff811ab8f4>] ? blk_peek_request+0xb4/0x1f0
[ 3038.290721]  [<ffffffff813506a2>] ? schedule_timeout+0x152/0x230
[ 3038.290721]  [<ffffffff810496a0>] ? run_timer_softirq+0x240/0x240
[ 3038.290721]  [<ffffffffa00b3c0f>] ? xfsbufd+0x8f/0x120 [xfs]
[ 3038.290721]  [<ffffffffa00b3b80>] ? xfs_bdstrat_cb+0x60/0x60 [xfs]
[ 3038.290721]  [<ffffffffa00b3b80>] ? xfs_bdstrat_cb+0x60/0x60 [xfs]
[ 3038.290721]  [<ffffffff8105b7d2>] ? kthread+0xa2/0xb0
[ 3038.290721]  [<ffffffff81353919>] ? kernel_thread_helper+0x9/0x20
[ 3038.290721]  [<ffffffff813522ea>] ? retint_restore_args+0x6/0xd
[ 3038.290721]  [<ffffffff8105b730>] ? kthread_worker_fn+0x140/0x140
[ 3038.290721]  [<ffffffff81353910>] ? gs_change+0x1b/0x1b
[ 3038.290721] rsync           D 0000000000000000     0  3957      1
0x00000004
[ 3038.290721]  ffff880019559440 0000000000000086 0000000000000400
0000000000000000
[ 3038.290721]  ffff88001820b600 000000000000cd80 ffff880019559830
ffffffff81030fa0
[ 3038.290721]  000000000000cd80 ffff880019559830 ffff880019559830
000000000000cd80
[ 3038.290721] Call Trace:
[ 3038.290721]  [<ffffffff81030fa0>] ? check_preempt_wakeup+0x140/0x140
[ 3038.290721]  [<ffffffff8109d304>] ? account_page_dirtied+0x74/0xa0
[ 3038.290721]  [<ffffffff81110e99>] ?
__block_commit_write.clone.17+0xa9/0xf0
[ 3038.290721]  [<ffffffffa009aef6>] ? xlog_grant_log_space+0x236/0x340
[xfs]
[ 3038.290721]  [<ffffffff81036ef0>] ? try_to_wake_up+0x280/0x280
[ 3038.290721]  [<ffffffffa00a83bb>] ? xfs_trans_reserve+0x9b/0x200 [xfs]
[ 3038.290721]  [<ffffffffa00a8237>] ? xfs_trans_alloc+0x97/0xb0 [xfs]
[ 3038.290721]  [<ffffffffa00a6b46>] ? xfs_rename+0x156/0x710 [xfs]
[ 3038.290721]  [<ffffffff810e9f21>] ? complete_walk+0x71/0x120
[ 3038.290721]  [<ffffffffa00badd0>] ? xfs_vn_rename+0x60/0x70 [xfs]
[ 3038.290721]  [<ffffffff810eb696>] ? vfs_rename+0x3c6/0x410
[ 3038.290721]  [<ffffffff810f822e>] ? d_lookup+0x2e/0x60
[ 3038.290721]  [<ffffffff810e994b>] ? __lookup_hash+0xab/0x1c0
[ 3038.290721]  [<ffffffff810ef406>] ? sys_renameat+0x286/0x2e0
[ 3038.290721]  [<ffffffffa0090c2b>] ? xfs_iunlock+0x4b/0xa0 [xfs]
[ 3038.290721]  [<ffffffffa00ac9f9>] ? xfs_setattr+0x3d9/0x7c0 [xfs]
[ 3038.290721]  [<ffffffff810fb30c>] ? notify_change+0x27c/0x3a0
[ 3038.290721]  [<ffffffff810f60ab>] ? dput+0x3b/0x190
[ 3038.290721]  [<ffffffff81352a79>] ? system_call_fastpath+0x16/0x1b
[ 3038.290721]  [<ffffffff81352a17>] ? system_call_after_swapgs+0x17/0x63
[ 3038.290721]  [<ffffffff81352a17>] ? system_call_after_swapgs+0x17/0x63

3038.290721] [<ffffffff81352a17>] ? system_call_after_swapgs+0x17/0x63

If i can do some more debug pleas let me know, i'll prepare it. Thanks for help.
Marcin Mirosław

_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

Marcin M

author

2011-10-15 12:28 UTC #1 lore raw

One more thing, probably doesn't have matter, this is Xen HVM.

_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

Amit Sahrawat

2011-10-15 16:04 UTC #2 lore raw

Hi Marcin,
Can you share the Free blocks for the disk at the time of this issue(df -k)? It seems that the disk do not have enough free space to reserve a transaction.
Also, the logs also seems to be mixed. The stucked position really seems to be :
Function: xlog_grant_log_space()

	/* Is there space or do we need to sleep? */
	spin_lock(&log->l_grant_lock);

Is there any other activity which was done on the disk before you observed these hang traces?At first it does seems to hang XFS, next if you issue a 'sync' you will observe that sync will also turn to TASK_UNINTERRUPTIBLE 'D' state.

Thanks & Regards,
Amit Sahrawat

Quoted 7 lines · Marcin M

One more thing, probably doesn't have matter, this is Xen HVM.
_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

Marcin Mirosław

2011-10-15 17:45 UTC #3 lore raw

W dniu 2011-10-15 18:04, Amit Sahrawat pisze:

Quoted 6 lines

Hi Marcin,
Can you share the Free blocks for the disk at the time of this issue(df -k)? It seems that the disk do not have enough free space to reserve a transaction.
Also, the logs also seems to be mixed. The stucked position really seems to be :
Function: xlog_grant_log_space()

Quoted 6 lines

	/* Is there space or do we need to sleep? */
	spin_lock(&log->l_grant_lock);
Is there any other activity which was done on the disk before you observed these hang traces?At first it does seems to hang XFS, next if you issue a 'sync' you will observe that sync will also turn to TASK_UNINTERRUPTIBLE 'D' state.

Hi Amit.
# df -kT /dev/sda11
Filesystem Type 1K-blocks Used Available Use% Mounted on
/dev/sda11 xfs 3840937 2354891 1486046 62% /mnt/cdrom

No, i only run rsync to partition located at /dev/sda11. Meseems the main information is size of log. Maybe there is board case when log is minimal size (such small as mkfs allow).
Regards.

_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

Dave Chinner

2011-10-15 22:09 UTC #4 lore raw

In reply to Marcin M

Quoted 5 lines · Marcin M

Hello!
I've noticed strange problem with xfs. I've created filesystem with blocksize=1024 and log as small as it possible. Next i'm copying files using rsync, after sometime rsync hangs in D state. So i can't kill it, i've got to reboot hosts. In dmesg i'm getting such messages:

Known problem - it's a log space hang. You can often get stuff moving again via "echo 2 > /proc/sys/vm/drop_caches".

That said, Christoph's fixes for the 3.0.x kernel series are here:

http://oss.sgi.com/archives/xfs/2011-10/msg00305.html

Cheers,

Dave.

Signature · 7 lines

Dave Chinner
[email protected]

_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

Marcin Mirosław

2011-10-15 22:16 UTC #5 lore raw

W dniu 2011-10-16 00:09, Dave Chinner pisze:

Quoted 2 lines

Known problem - it's a log space hang. You can often get stuff moving again via "echo 2 > /proc/sys/vm/drop_caches".

It didn't help in my case. You said "often" not "always" maybe this is reason:)

Quoted 3 lines

That said, Christoph's fixes for the 3.0.x kernel series are here:
http://oss.sgi.com/archives/xfs/2011-10/msg00305.html

I'll try patches and i'll say if it resolve my problem. Thanks for link.

_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

Marcin Mirosław

2011-10-16 11:48 UTC #6 lore raw

In reply to Dave Chinner

W dniu 2011-10-16 00:09, Dave Chinner pisze:

Quoted 6 lines

Known problem - it's a log space hang. You can often get stuff moving again via "echo 2 > /proc/sys/vm/drop_caches".
That said, Christoph's fixes for the 3.0.x kernel series are here:
http://oss.sgi.com/archives/xfs/2011-10/msg00305.html

Thanks for link. I've tried kernel linux-3.1-rc9, xfs behaves better but still is something not right. I'm rsyncincg many files, after sometime rsync hangs, it looks like do nothing for about 30-90 seconds and continues copying. I did run "sync" when rsync was hanging and sync also hangs. It looks like xfs has hiccup.
Regards,
Marcin

_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

Christoph Hellwig

2011-10-16 12:35 UTC #7 lore raw

Quoted 5 lines · Marcin Miros?aw

Thanks for link. I've tried kernel linux-3.1-rc9, xfs behaves better but still is something not right. I'm rsyncincg many files, after sometime rsync hangs, it looks like do nothing for about 30-90 seconds and continues copying. I did run "sync" when rsync was hanging and sync also hangs. It looks like xfs has hiccup.

3.1-rc9 does not include these fixes yet, you'll either need to get Linus' latests git tree or apply these patches manually.

I'd also love to see the output of dmesg after doing a

'echo t > /proc/sysrq-trigger'

from these hangs if you can still reproduce them.

_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

Marcin Mirosław

2011-10-16 13:38 UTC #8 lore raw

W dniu 2011-10-16 14:35, Christoph Hellwig pisze:

Quoted 2 lines

3.1-rc9 does not include these fixes yet, you'll either need to get Linus' latests git tree or apply these patches manually.

I checked random patch (
http://oss.sgi.com/archives/xfs/2011-10/msg00309.html ) it was in tree so i though other patches from series was in tree. But they don't :)

Quoted 5 lines

I'd also love to see the output of dmesg after doing a
'echo t > /proc/sysrq-trigger'
from these hangs if you can still reproduce them.

I tried kernel from git master. I can't reproduce problem now. Thank you for help!

_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

Christoph Hellwig

2011-10-16 16:05 UTC #9 lore raw

Quoted 6 lines · Marcin Miros?aw

Quoted 2 lines
3.1-rc9 does not include these fixes yet, you'll either need to get Linus' latests git tree or apply these patches manually.
I checked random patch (
http://oss.sgi.com/archives/xfs/2011-10/msg00309.html ) it was in tree so i though other patches from series was in tree. But they don't :)

Sorry, that was the 3.0-stable backport that includes two additional patches.

Quoted 8 lines

Quoted 5 lines
I'd also love to see the output of dmesg after doing a
'echo t > /proc/sysrq-trigger'
from these hangs if you can still reproduce them.
I tried kernel from git master. I can't reproduce problem now. Thank you for help!

Good to know. If anything strange happens again please notify the list.

_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs