Date:	Sat, 13 Jun 2009 14:27:22 -0400
From:	Bart Trojanowski <bart@...ie.net>
To:	David Howells <dhowells@...hat.com>, linux-kernel@...r.kernel.org
Cc:	linux-cachefs@...hat.com, linux-nfs@...r.kernel.org,
	linux-mm@...ck.org
Subject: [v2.6.30 nfs+fscache] kswapd1: blocked for more than 120 seconds

Hi,

I ran into a fscache lockup.  The code seems to be waiting for a page
write event which never comes.  I am CC'ing the nfs and MM lists just in
case there is something obvious here.

More info follows, and let me know if you need anything else.  I'll
leave the box in this state until kswapd hang (D state) causes me other
issues :)

I am running:
  - on an 8-way amd64 system;
  - linux v2.6.30 with the following enabled:
        CONFIG_PREEMPT_VOLUNTARY=y
        ...
        CONFIG_FSCACHE=m
        CONFIG_FSCACHE_STATS=y
        CONFIG_FSCACHE_HISTOGRAM=y
        CONFIG_CACHEFILES=m
        CONFIG_CACHEFILES_HISTOGRAM=y
        ...
        CONFIG_NFS_FSCACHE=y
        (see attached config for the rest)
  - cachefilesd_0.9-2 (from debian/testing)
  - nfs-utils-1.2.0-2 (from debian/testing)
  - my $HOME dir is mounted with rw,nodev,fsc,udp,rsize=32768,wsize=32768,soft,intr,nfsvers=3
  - my cachefilesd uses xfs on MD raid0 volume over two SATA disks

I installed and setup everything yesterday and was pretty happy with how
it worked.  Today, I thought I would look at the /proc/fs/fscache/
stats.  More specifically I ran 'watch -n1 -d cat /proc/fs/fscache/*' in
one terminal.  In another terminal I decided to time catting mail/**/*
to /dev/null before and after seeding the cache (and a remount).  I
didn't get that far.  cat hung in a D state.  dmesg shows:

INFO: task kswapd0:423 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kswapd0       D 0000000000000000     0   423      2
 ffff88023e5a3950 0000000000000046 ffff88023e5a38c0 0000000000000002
 0000000000000002 ffffe20005368108 0000000000012cc0 000000000000d4a8
 ffff88023e5a8000 ffff88023f0bb160 ffff88023e5a8598 000000028035a005
Call Trace:
 [<ffffffff8022653f>] ? default_spin_lock_flags+0x9/0xe
 [<ffffffff805890de>] schedule+0xe/0x22
 [<ffffffffa0171e24>] __fscache_wait_on_page_write+0x98/0xb4 [fscache]
 [<ffffffff80258bac>] ? autoremove_wake_function+0x0/0x3d
 [<ffffffffa01c1216>] nfs_fscache_release_page+0x53/0xcb [nfs]
 [<ffffffffa019ca5c>] nfs_release_page+0x41/0x4a [nfs]
 [<ffffffff80299fd8>] try_to_release_page+0x34/0x3d
 [<ffffffff802a59bc>] shrink_page_list+0x4db/0x681
 [<ffffffff802a4a34>] ? isolate_pages_global+0x192/0x232
 [<ffffffff80374233>] ? kmem_free+0x2b/0x34
 [<ffffffff802a61d7>] shrink_list+0x2af/0x5da
 [<ffffffff80235a5d>] ? update_curr+0x75/0x152
 [<ffffffff8023854b>] ? enqueue_entity+0x22b/0x234
 [<ffffffff8022653f>] ? default_spin_lock_flags+0x9/0xe
 [<ffffffff802a67a4>] shrink_zone+0x2a2/0x34f
 [<ffffffff803b2173>] ? __up_read+0x92/0x9b
 [<ffffffff802a6998>] ? shrink_slab+0x147/0x159
 [<ffffffff802a70d3>] kswapd+0x473/0x63c
 [<ffffffff802a48a2>] ? isolate_pages_global+0x0/0x232
 [<ffffffff80258bac>] ? autoremove_wake_function+0x0/0x3d
 [<ffffffff802a6c60>] ? kswapd+0x0/0x63c
 [<ffffffff802a6c60>] ? kswapd+0x0/0x63c
 [<ffffffff80258783>] kthread+0x5b/0x88
 [<ffffffff8020cd4a>] child_rip+0xa/0x20
 [<ffffffff80258728>] ? kthread+0x0/0x88
 [<ffffffff8020cd40>] ? child_rip+0x0/0x20

INFO: task kswapd1:424 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kswapd1       D 0000000000000000     0   424      2
 ffff88023e5b1950 0000000000000046 0000000000000082 ffff88038a92aea0
 0000000000000002 ffffffff8020c6ce 0000000000012cc0 000000000000d4a8
 ffff88023e5a98b0 ffff88023f103160 ffff88023e5a9e48 000000073e5a98b0
Call Trace:
 [<ffffffff8020c6ce>] ? common_interrupt+0xe/0x13
 [<ffffffff8022653f>] ? default_spin_lock_flags+0x9/0xe
 [<ffffffff805890de>] schedule+0xe/0x22
 [<ffffffffa0171e24>] __fscache_wait_on_page_write+0x98/0xb4 [fscache]
 [<ffffffff80258bac>] ? autoremove_wake_function+0x0/0x3d
 [<ffffffffa0218276>] ? cachefiles_uncache_page+0x16/0x1a [cachefiles]
 [<ffffffffa01c1216>] nfs_fscache_release_page+0x53/0xcb [nfs]
 [<ffffffffa019ca5c>] nfs_release_page+0x41/0x4a [nfs]
 [<ffffffff80299fd8>] try_to_release_page+0x34/0x3d
 [<ffffffff802a59bc>] shrink_page_list+0x4db/0x681
 [<ffffffff802a61d7>] shrink_list+0x2af/0x5da
 [<ffffffff80235a5d>] ? update_curr+0x75/0x152
 [<ffffffff80236416>] ? dequeue_entity+0x20/0x1e4
 [<ffffffff8020a654>] ? __switch_to+0xb4/0x273
 [<ffffffff8023636b>] ? set_next_entity+0x99/0xea
 [<ffffffff8023f5b5>] ? finish_task_switch+0x57/0xf0
 [<ffffffff802a67a4>] shrink_zone+0x2a2/0x34f
 [<ffffffff803b2173>] ? __up_read+0x92/0x9b
 [<ffffffff802a70d3>] kswapd+0x473/0x63c
 [<ffffffff802a48a2>] ? isolate_pages_global+0x0/0x232
 [<ffffffff80258bac>] ? autoremove_wake_function+0x0/0x3d
 [<ffffffff802a6c60>] ? kswapd+0x0/0x63c
 [<ffffffff802a6c60>] ? kswapd+0x0/0x63c
 [<ffffffff80258783>] kthread+0x5b/0x88
 [<ffffffff8020cd4a>] child_rip+0xa/0x20
 [<ffffffff80258728>] ? kthread+0x0/0x88
 [<ffffffff8020cd40>] ? child_rip+0x0/0x20

INFO: task cat:6151 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
cat           D 0000000000000000     0  6151   6021
 ffff8803c41997d8 0000000000000086 00000002c4199738 ffff88043e676c00
 0000000000000002 ffff88043e676ce8 0000000000012cc0 000000000000d4a8
 ffff88043e56ca10 ffff88023f0e8000 ffff88043e56cfa8 00000004000002b2
Call Trace:
 [<ffffffff8058b097>] ? _spin_lock+0xe/0x12
 [<ffffffff805890de>] schedule+0xe/0x22
 [<ffffffff8058af12>] __down_read+0xa8/0xc2
 [<ffffffffa02161de>] ? cachefiles_has_space+0x43/0x187 [cachefiles]
 [<ffffffff8058a008>] down_read+0x1e/0x22
 [<ffffffff80359282>] xfs_ilock+0x37/0x62
 [<ffffffff80375c3e>] xfs_vm_bmap+0x2f/0x6c
 [<ffffffffa02187a2>] cachefiles_read_or_alloc_pages+0x1df/0x95e [cachefiles]
 [<ffffffff8029e89a>] ? __rmqueue+0x24/0x1f3
 [<ffffffff8029eaee>] ? rmqueue_bulk+0x85/0x99
 [<ffffffff802abb6b>] ? zone_statistics+0x65/0x6a
 [<ffffffff80258ac0>] ? bit_waitqueue+0x17/0xa8
 [<ffffffff80258ba7>] ? wake_up_bit+0x23/0x28
 [<ffffffffa0170666>] ? fscache_run_op+0x2d/0x47 [fscache]
 [<ffffffffa01718f3>] __fscache_read_or_alloc_pages+0x1d2/0x24f [fscache]
 [<ffffffffa01c0e7a>] __nfs_readpages_from_fscache+0x84/0x171 [nfs]
 [<ffffffffa01a755e>] nfs_readpages+0x11f/0x1d4 [nfs]
 [<ffffffff802c182c>] ? alloc_pages_current+0xbe/0xc7
 [<ffffffff802a2e56>] __do_page_cache_readahead+0x10d/0x197
 [<ffffffff802a314f>] ondemand_readahead+0x17d/0x18f
 [<ffffffff802a31db>] page_cache_async_readahead+0x7a/0x86
 [<ffffffff8029c191>] generic_file_aio_read+0x27c/0x5c2
 [<ffffffffa019d941>] nfs_file_read+0xeb/0xfe [nfs]
 [<ffffffff802ccc62>] do_sync_read+0xec/0x132
 [<ffffffff802121e6>] ? native_sched_clock+0x32/0x60
 [<ffffffff80258bac>] ? autoremove_wake_function+0x0/0x3d
 [<ffffffff80589056>] ? thread_return+0x41/0xbb
 [<ffffffff8038da48>] ? security_file_permission+0x16/0x18
 [<ffffffff802cd85a>] vfs_read+0xb0/0x159
 [<ffffffff802cd9d1>] sys_read+0x4c/0x74
 [<ffffffff8020bd72>] system_call_fastpath+0x16/0x1b

INFO: task kslowd:6259 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kslowd        D 0000000000000000     0  6259      2
 ffff8802a8991420 0000000000000046 0000000000000082 ffff88038a92aaa0
 0000000000000002 0000000000000010 0000000000012cc0 000000000000d4a8
 ffff88042a9798b0 ffff88023f0f4a10 ffff88042a979e48 00000006803b1545
Call Trace:
 [<ffffffff8022653f>] ? default_spin_lock_flags+0x9/0xe
 [<ffffffff805890de>] schedule+0xe/0x22
 [<ffffffffa0171e24>] __fscache_wait_on_page_write+0x98/0xb4 [fscache]
 [<ffffffff80258bac>] ? autoremove_wake_function+0x0/0x3d
 [<ffffffffa01c1216>] nfs_fscache_release_page+0x53/0xcb [nfs]
 [<ffffffffa019ca5c>] nfs_release_page+0x41/0x4a [nfs]
 [<ffffffff80299fd8>] try_to_release_page+0x34/0x3d
 [<ffffffff802a59bc>] shrink_page_list+0x4db/0x681
 [<ffffffff802a61d7>] shrink_list+0x2af/0x5da
 [<ffffffff8022653f>] ? default_spin_lock_flags+0x9/0xe
 [<ffffffff803b20d2>] ? __up_write+0x115/0x124
 [<ffffffff802a67a4>] shrink_zone+0x2a2/0x34f
 [<ffffffff802601f2>] ? getnstimeofday+0x5c/0xb8
 [<ffffffff802a78c2>] try_to_free_pages+0x26f/0x3db
 [<ffffffff802a48a2>] ? isolate_pages_global+0x0/0x232
 [<ffffffff803b0799>] ? __prop_inc_single+0x37/0x3c
 [<ffffffff802a1047>] __alloc_pages_internal+0x29b/0x448
 [<ffffffff802c182c>] alloc_pages_current+0xbe/0xc7
 [<ffffffff802c62b4>] new_slab+0x5c/0x287
 [<ffffffff802c66e7>] __slab_alloc+0x208/0x3e9
 [<ffffffff80374188>] ? kmem_zone_alloc+0x6c/0xb7
 [<ffffffff80374188>] ? kmem_zone_alloc+0x6c/0xb7
 [<ffffffff802c6bce>] kmem_cache_alloc+0x7c/0xf1
 [<ffffffff80374188>] kmem_zone_alloc+0x6c/0xb7
 [<ffffffff803741e7>] kmem_zone_zalloc+0x14/0x35
 [<ffffffff8036db8d>] xfs_trans_dup+0x20/0xec
 [<ffffffff8035c210>] xfs_itruncate_finish+0x1d6/0x28a
 [<ffffffff80371f7d>] xfs_free_eofblocks+0x1c9/0x20f
 [<ffffffff802ccb30>] ? do_sync_write+0xec/0x132
 [<ffffffff80372953>] xfs_release+0x182/0x193
 [<ffffffff803785e9>] xfs_file_release+0x15/0x19
 [<ffffffff802cdf6d>] __fput+0xe4/0x1a5
 [<ffffffff802ce04b>] fput+0x1d/0x1f
 [<ffffffffa021842e>] cachefiles_write_page+0x1b4/0x205 [cachefiles]
 [<ffffffffa0171421>] fscache_write_op+0xd9/0x17f [fscache]
 [<ffffffffa016ffb6>] fscache_op_execute+0x41/0x6e [fscache]
 [<ffffffff80299bbe>] slow_work_thread+0x280/0x44a
 [<ffffffff8023cf59>] ? default_wake_function+0x12/0x14
 [<ffffffff80258bac>] ? autoremove_wake_function+0x0/0x3d
 [<ffffffff8029993e>] ? slow_work_thread+0x0/0x44a
 [<ffffffff8029993e>] ? slow_work_thread+0x0/0x44a
 [<ffffffff80258783>] kthread+0x5b/0x88
 [<ffffffff8020cd4a>] child_rip+0xa/0x20
 [<ffffffff80258728>] ? kthread+0x0/0x88
 [<ffffffff8020cd40>] ? child_rip+0x0/0x20

... and then it just repeats the stuff above.

-Bart

-- 
				WebSig: http://www.jukie.net/~bart/sig/

View attachment "config" of type "text/plain" (68539 bytes)

Powered by blists - more mailing lists