Running xfstests against a local server on XFS:
generic/075 23s ...[ 605.063602] nfs: server 127.0.0.1 not responding, still trying
[ 605.064398] general protection fault: 0000 [#1] SMP
[ 605.064994] Modules linked in:
[ 605.065386] CPU: 2 PID: 3469 Comm: nfsd Not tainted 3.13.0-rc2 #58
[ 605.066051] Hardware name: Bochs Bochs, BIOS Bochs 01/01/2007
[ 605.066704] task: ffff8800762e6010 ti: ffff8800756d8000 task.ti: ffff8800756d8000
[ 605.066843] RIP: 0010:[<ffffffff81331f1b>] [<ffffffff81331f1b>] lru_put_end+0x1b/0x60
[ 605.066843] RSP: 0018:ffff8800756d9d28 EFLAGS: 00010246
[ 605.066843] RAX: dead000000200200 RBX: ffff8800754a4e90 RCX: dead000000100100
[ 605.066843] RDX: ffff8800754a4ea0 RSI: ffff8800762e66c0 RDI: ffff8800754a4e90
[ 605.066843] RBP: ffff8800756d9d28 R08: 0000000000000006 R09: 0000000000000001
[ 605.066843] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000001
[ 605.066843] R13: 0000000000000000 R14: 000000000cb5731d R15: ffff88007b4dc000
[ 605.066843] FS: 0000000000000000(0000) GS:ffff88007fd00000(0000) knlGS:0000000000000000
[ 605.066843] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[ 605.066843] CR2: ffffffffff600400 CR3: 000000006fe87000 CR4: 00000000000006e0
[ 605.066843] Stack:
[ 605.066843] ffff8800756d9d88 ffffffff81332498 ffff88007cf33600 ffffffff0cb5731d
[ 605.066843] 0000000300000002 4d36e16d00000006 ffff88007b4dc000 ffff88007b4dc000
[ 605.066843] ffffffff82211230 ffff880076216018 ffffffff822111a0 ffff880076216018
[ 605.066843] Call Trace:
[ 605.066843] [<ffffffff81332498>] nfsd_cache_lookup+0x3c8/0x730
[ 605.066843] [<ffffffff8132763e>] nfsd_dispatch+0x5e/0x1b0
[ 605.066843] [<ffffffff81b6f551>] svc_process+0x4b1/0x760
[ 605.066843] [<ffffffff81326f9f>] nfsd+0xbf/0x130
[ 605.066843] [<ffffffff81326ee0>] ? nfsd_destroy+0xc0/0xc0
[ 605.066843] [<ffffffff810b6b0f>] kthread+0xdf/0x100
[ 605.066843] [<ffffffff81c4130b>] ? _raw_spin_unlock_irq+0x2b/0x40
[ 605.066843] [<ffffffff810b6a30>] ? __init_kthread_worker+0x70/0x70
[ 605.066843] [<ffffffff81c4970c>] ret_from_fork+0x7c/0xb0
[ 605.066843] [<ffffffff810b6a30>] ? __init_kthread_worker+0x70/0x70
On Tue, Dec 03, 2013 at 05:59:38AM -0500, Jeff Layton wrote:
>
> Actually, it's pretty unlikely that this would get pruned here.
> lru_put_end updates the timestamp on the entry, so the
> prune_cache_entries run would have to take more than 120s and prune
> everything off of the list.
>
> The real bug is that we can later find the entry in the hash that we
> intend to reuse and then free that cache entry. The safe thing to do
> here is to just unhash the entry that we intend to use so that it can't
> be found or pruned.
>
> I sent a patch that should fix this the correct way:
>
> [PATCH] nfsd: when reusing an existing repcache entry, unhash it first
>
Yes, you are right. Thanks.
On Sun, 1 Dec 2013 02:29:54 -0800
Christoph Hellwig <[email protected]> wrote:
>
> Running xfstests against a local server on XFS:
>
> generic/075 23s ...[ 605.063602] nfs: server 127.0.0.1 not responding, still trying
> [ 605.064398] general protection fault: 0000 [#1] SMP
> [ 605.064994] Modules linked in:
> [ 605.065386] CPU: 2 PID: 3469 Comm: nfsd Not tainted 3.13.0-rc2 #58
> [ 605.066051] Hardware name: Bochs Bochs, BIOS Bochs 01/01/2007
> [ 605.066704] task: ffff8800762e6010 ti: ffff8800756d8000 task.ti: ffff8800756d8000
> [ 605.066843] RIP: 0010:[<ffffffff81331f1b>] [<ffffffff81331f1b>] lru_put_end+0x1b/0x60
> [ 605.066843] RSP: 0018:ffff8800756d9d28 EFLAGS: 00010246
> [ 605.066843] RAX: dead000000200200 RBX: ffff8800754a4e90 RCX: dead000000100100
> [ 605.066843] RDX: ffff8800754a4ea0 RSI: ffff8800762e66c0 RDI: ffff8800754a4e90
> [ 605.066843] RBP: ffff8800756d9d28 R08: 0000000000000006 R09: 0000000000000001
> [ 605.066843] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000001
> [ 605.066843] R13: 0000000000000000 R14: 000000000cb5731d R15: ffff88007b4dc000
> [ 605.066843] FS: 0000000000000000(0000) GS:ffff88007fd00000(0000) knlGS:0000000000000000
> [ 605.066843] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
> [ 605.066843] CR2: ffffffffff600400 CR3: 000000006fe87000 CR4: 00000000000006e0
> [ 605.066843] Stack:
> [ 605.066843] ffff8800756d9d88 ffffffff81332498 ffff88007cf33600 ffffffff0cb5731d
> [ 605.066843] 0000000300000002 4d36e16d00000006 ffff88007b4dc000 ffff88007b4dc000
> [ 605.066843] ffffffff82211230 ffff880076216018 ffffffff822111a0 ffff880076216018
> [ 605.066843] Call Trace:
> [ 605.066843] [<ffffffff81332498>] nfsd_cache_lookup+0x3c8/0x730
> [ 605.066843] [<ffffffff8132763e>] nfsd_dispatch+0x5e/0x1b0
> [ 605.066843] [<ffffffff81b6f551>] svc_process+0x4b1/0x760
> [ 605.066843] [<ffffffff81326f9f>] nfsd+0xbf/0x130
> [ 605.066843] [<ffffffff81326ee0>] ? nfsd_destroy+0xc0/0xc0
> [ 605.066843] [<ffffffff810b6b0f>] kthread+0xdf/0x100
> [ 605.066843] [<ffffffff81c4130b>] ? _raw_spin_unlock_irq+0x2b/0x40
> [ 605.066843] [<ffffffff810b6a30>] ? __init_kthread_worker+0x70/0x70
> [ 605.066843] [<ffffffff81c4970c>] ret_from_fork+0x7c/0xb0
> [ 605.066843] [<ffffffff810b6a30>] ? __init_kthread_worker+0x70/0x70
Looks like a similar oops to the one reported here:
https://bugzilla.redhat.com/show_bug.cgi?id=1025907
Do you have a way to reproduce this reliably?
--
Jeff Layton <[email protected]>
On Mon, Dec 02, 2013 at 12:22:19PM -0500, Jeff Layton wrote:
> Looks like a similar oops to the one reported here:
>
> https://bugzilla.redhat.com/show_bug.cgi?id=1025907
>
> Do you have a way to reproduce this reliably?
Seem to happen about 2/3s of the time when running xfstests on a v3
export for me. The other one third create a different lockup in the
same test that I'm looking at at the moment.
On Tue, 3 Dec 2013 11:33:42 +0800
Minlan Wang <[email protected]> wrote:
> On Mon, Dec 02, 2013 at 09:25:47AM -0800, Christoph Hellwig wrote:
> > On Mon, Dec 02, 2013 at 12:22:19PM -0500, Jeff Layton wrote:
> > > Looks like a similar oops to the one reported here:
> > >
> > > https://bugzilla.redhat.com/show_bug.cgi?id=1025907
> > >
> > > Do you have a way to reproduce this reliably?
> >
> > Seem to happen about 2/3s of the time when running xfstests on a v3
> > export for me. The other one third create a different lockup in the
> > same test that I'm looking at at the moment.
> >
> I reviewed the code of nfsd_cache_lookup(), this part makes me
> suspicious:
> in nfsd_cache_lookup():
> The first entry in lru_head is keeped for recycle later:
> if (!list_empty(&lru_head)) {
> rp = list_first_entry(&lru_head, struct svc_cacherep, c_lru);
> if (nfsd_cache_entry_expired(rp) ||
> num_drc_entries >= max_drc_entries) {
> lru_put_end(rp);
> prune_cache_entries();
> goto search_cache;
> }
> }
> But in prune_cache_entries(), there's no guarantee that it won't be freed: if
> all entries in lru_head is expired, all of them will be freed.
> So, later in the search_cache part, if rp from the first entry in lru_head is reused, would we
> run into some illegal memory acess, or the problem happened in this
> thread?
Actually, it's pretty unlikely that this would get pruned here.
lru_put_end updates the timestamp on the entry, so the
prune_cache_entries run would have to take more than 120s and prune
everything off of the list.
The real bug is that we can later find the entry in the hash that we
intend to reuse and then free that cache entry. The safe thing to do
here is to just unhash the entry that we intend to use so that it can't
be found or pruned.
I sent a patch that should fix this the correct way:
[PATCH] nfsd: when reusing an existing repcache entry, unhash it first
--
Jeff Layton <[email protected]>
On Mon, Dec 02, 2013 at 09:25:47AM -0800, Christoph Hellwig wrote:
> On Mon, Dec 02, 2013 at 12:22:19PM -0500, Jeff Layton wrote:
> > Looks like a similar oops to the one reported here:
> >
> > https://bugzilla.redhat.com/show_bug.cgi?id=1025907
> >
> > Do you have a way to reproduce this reliably?
>
> Seem to happen about 2/3s of the time when running xfstests on a v3
> export for me. The other one third create a different lockup in the
> same test that I'm looking at at the moment.
>
I reviewed the code of nfsd_cache_lookup(), this part makes me
suspicious:
in nfsd_cache_lookup():
The first entry in lru_head is keeped for recycle later:
if (!list_empty(&lru_head)) {
rp = list_first_entry(&lru_head, struct svc_cacherep, c_lru);
if (nfsd_cache_entry_expired(rp) ||
num_drc_entries >= max_drc_entries) {
lru_put_end(rp);
prune_cache_entries();
goto search_cache;
}
}
But in prune_cache_entries(), there's no guarantee that it won't be freed: if
all entries in lru_head is expired, all of them will be freed.
So, later in the search_cache part, if rp from the first entry in lru_head is reused, would we
run into some illegal memory acess, or the problem happened in this
thread?