Hi all,
I've been running into the following warning on an arm64 system running
3.17-rc6 with 64k pages. I've been unable to reproduce with a smaller page
size (4k).
I don't yet have a concrete reproducer, but I've seen it hit a few times
today just running a machine with an NFS root filesystem and using ssh.
The warning seems to happen in parallel on the two CPUs, but I'm pretty
confident that our test_and_clear_bit implementation has the relevant
atomic instructions and memory barriers.
Any ideas?
Will
--->8
------------[ cut here ]------------
WARNING: CPU: 1 PID: 1023 at fs/nfs/write.c:743 nfs_inode_remove_request+0xe4/0xf0()
Modules linked in:
CPU: 1 PID: 1023 Comm: kworker/1:2 Not tainted 3.17.0-rc6 #1
Workqueue: nfsiod rpc_async_release
Call trace:
[<fffffe0000096410>] dump_backtrace+0x0/0x130
[<fffffe0000096550>] show_stack+0x10/0x1c
[<fffffe00004cda94>] dump_stack+0x74/0xbc
[<fffffe00000b4d20>] warn_slowpath_common+0x8c/0xb4
[<fffffe00000b4e0c>] warn_slowpath_null+0x14/0x20
[<fffffe000027a6a8>] nfs_inode_remove_request+0xe0/0xf0
[<fffffe000027b704>] nfs_write_completion+0xb4/0x150
[<fffffe0000276ef4>] nfs_pgio_release+0x34/0x44
[<fffffe00004ac2d0>] rpc_free_task+0x24/0x4c
[<fffffe00004ac5c0>] rpc_async_release+0xc/0x18
[<fffffe00000c89e8>] process_one_work+0x140/0x32c
[<fffffe00000c9338>] worker_thread+0x13c/0x470
[<fffffe00000cd9e4>] kthread+0xd0/0xe8
---[ end trace 6f044efb83f0811b ]---
------------[ cut here ]------------
WARNING: CPU: 0 PID: 621 at fs/nfs/write.c:743 nfs_inode_remove_request+0xe4/0xf0()
CPU: 0 PID: 621 Comm: kworker/0:2 Tainted: G W 3.17.0-rc6 #1
Workqueue: nfsiod rpc_async_release
Call trace:
[<fffffe0000096410>] dump_backtrace+0x0/0x130
[<fffffe0000096550>] show_stack+0x10/0x1c
[<fffffe00004cda94>] dump_stack+0x74/0xbc
[<fffffe00000b4d20>] warn_slowpath_common+0x8c/0xb4
[<fffffe00000b4e0c>] warn_slowpath_null+0x14/0x20
[<fffffe000027a6a8>] nfs_inode_remove_request+0xe0/0xf0
[<fffffe000027b704>] nfs_write_completion+0xb4/0x150
[<fffffe0000276ef4>] nfs_pgio_release+0x34/0x44
[<fffffe00004ac2d0>] rpc_free_task+0x24/0x4c
[<fffffe00004ac5c0>] rpc_async_release+0xc/0x18
[<fffffe00000c89e8>] process_one_work+0x140/0x32c
[<fffffe00000c9338>] worker_thread+0x13c/0x470
[<fffffe00000cd9e4>] kthread+0xd0/0xe8
---[ end trace 6f044efb83f0811c ]---
On Sep 23, 2014, at 9:03 AM, Will Deacon <[email protected]> wrote:
> Hi all,
>
> I've been running into the following warning on an arm64 system running
> 3.17-rc6 with 64k pages. I've been unable to reproduce with a smaller page
> size (4k).
>
> I don't yet have a concrete reproducer, but I've seen it hit a few times
> today just running a machine with an NFS root filesystem and using ssh.
> The warning seems to happen in parallel on the two CPUs, but I'm pretty
> confident that our test_and_clear_bit implementation has the relevant
> atomic instructions and memory barriers.
>
> Any ideas?
>
> Will
So it looks like we?re either calling nfs_inode_remove_request twice on a request,
or somehow not grabbing the inode reference for some request that is in the async
write path. It?s interesting that these come in pairs - that has to mean something!
Any more info on how to reproduce this would be really great. Unfortunately I don?t
have access to an arm64 system.
If it?s possible, could we get a packet trace around when this happens? This is pure
speculation, but this might have something to do the resend path - a commit fails
and all the requests on the commit list have to be resent.
Have you noticed any side effects from this? That WARN_ON_ONCE was added
to sanity test the new page group code and we need to fix this, but I?m wondering
if anything ?bad? happens?
-dros
>
> --->8
>
> ------------[ cut here ]------------
> WARNING: CPU: 1 PID: 1023 at fs/nfs/write.c:743 nfs_inode_remove_request+0xe4/0xf0()
> Modules linked in:
> CPU: 1 PID: 1023 Comm: kworker/1:2 Not tainted 3.17.0-rc6 #1
> Workqueue: nfsiod rpc_async_release
> Call trace:
> [<fffffe0000096410>] dump_backtrace+0x0/0x130
> [<fffffe0000096550>] show_stack+0x10/0x1c
> [<fffffe00004cda94>] dump_stack+0x74/0xbc
> [<fffffe00000b4d20>] warn_slowpath_common+0x8c/0xb4
> [<fffffe00000b4e0c>] warn_slowpath_null+0x14/0x20
> [<fffffe000027a6a8>] nfs_inode_remove_request+0xe0/0xf0
> [<fffffe000027b704>] nfs_write_completion+0xb4/0x150
> [<fffffe0000276ef4>] nfs_pgio_release+0x34/0x44
> [<fffffe00004ac2d0>] rpc_free_task+0x24/0x4c
> [<fffffe00004ac5c0>] rpc_async_release+0xc/0x18
> [<fffffe00000c89e8>] process_one_work+0x140/0x32c
> [<fffffe00000c9338>] worker_thread+0x13c/0x470
> [<fffffe00000cd9e4>] kthread+0xd0/0xe8
> ---[ end trace 6f044efb83f0811b ]---
>
> ------------[ cut here ]------------
> WARNING: CPU: 0 PID: 621 at fs/nfs/write.c:743 nfs_inode_remove_request+0xe4/0xf0()
> CPU: 0 PID: 621 Comm: kworker/0:2 Tainted: G W 3.17.0-rc6 #1
> Workqueue: nfsiod rpc_async_release
> Call trace:
> [<fffffe0000096410>] dump_backtrace+0x0/0x130
> [<fffffe0000096550>] show_stack+0x10/0x1c
> [<fffffe00004cda94>] dump_stack+0x74/0xbc
> [<fffffe00000b4d20>] warn_slowpath_common+0x8c/0xb4
> [<fffffe00000b4e0c>] warn_slowpath_null+0x14/0x20
> [<fffffe000027a6a8>] nfs_inode_remove_request+0xe0/0xf0
> [<fffffe000027b704>] nfs_write_completion+0xb4/0x150
> [<fffffe0000276ef4>] nfs_pgio_release+0x34/0x44
> [<fffffe00004ac2d0>] rpc_free_task+0x24/0x4c
> [<fffffe00004ac5c0>] rpc_async_release+0xc/0x18
> [<fffffe00000c89e8>] process_one_work+0x140/0x32c
> [<fffffe00000c9338>] worker_thread+0x13c/0x470
> [<fffffe00000cd9e4>] kthread+0xd0/0xe8
> ---[ end trace 6f044efb83f0811c ]---
On Sep 23, 2014, at 11:02 AM, Weston Andros Adamson <[email protected]> wrote:
> On Sep 23, 2014, at 10:59 AM, Weston Andros Adamson <[email protected]> wrote:
>
>> On Sep 23, 2014, at 10:53 AM, Will Deacon <[email protected]> wrote:
>>
>>> On Tue, Sep 23, 2014 at 02:59:38PM +0100, Will Deacon wrote:
>>>> On Tue, Sep 23, 2014 at 02:33:06PM +0100, Weston Andros Adamson wrote:
>>>>> Any more info on how to reproduce this would be really great. Unfortunately I don?t
>>>>> have access to an arm64 system.
>>>>
>>>> I've not spotted a pattern other than using 64k pages, yet. If I manage to
>>>> get a reproducer, I'll let you know.
>>>>
>>>>> If it?s possible, could we get a packet trace around when this happens? This is pure
>>>>> speculation, but this might have something to do the resend path - a commit fails
>>>>> and all the requests on the commit list have to be resent.
>>>>
>>>> Sure, once I can reproduce it reliably, then I'll try to do that.
>>>
>>> Right, a bunch of DDing from /dev/zero over an ssh session triggers this
>>> very quickly. I've put a binary tcpdump here:
>>>
>>> http://www.willdeacon.ukfsn.org/bitbucket/oopsen/nfs/tcpdump.bin
>>>
>>> You may want to filter out the ssh packets. The only `interesting' thing to
>>> me is a retransmission about half way through, but I don't know what I'm
>>> looking for.
>>>
>>> The NFS server is 10.1.203.204 and the client is 10.1.203.24.
>>
>> Thanks! You are using NFSv2, so there are no commits - that rules out my hunch.
>
> Wait a second - the whole point of this extra reference (that the WARN_ON_ONCE is
> related to) is to handle the pass off to commit lists.
>
> Maybe I?m just doing the wrong thing here with NFSv2!
>
> More soon.
Actually, can you see if this is reproducible with NFSv3?
Thanks,
-dros
On Tue, Sep 23, 2014 at 02:59:38PM +0100, Will Deacon wrote:
> On Tue, Sep 23, 2014 at 02:33:06PM +0100, Weston Andros Adamson wrote:
> > Any more info on how to reproduce this would be really great. Unfortunately I don’t
> > have access to an arm64 system.
>
> I've not spotted a pattern other than using 64k pages, yet. If I manage to
> get a reproducer, I'll let you know.
>
> > If it’s possible, could we get a packet trace around when this happens? This is pure
> > speculation, but this might have something to do the resend path - a commit fails
> > and all the requests on the commit list have to be resent.
>
> Sure, once I can reproduce it reliably, then I'll try to do that.
Right, a bunch of DDing from /dev/zero over an ssh session triggers this
very quickly. I've put a binary tcpdump here:
http://www.willdeacon.ukfsn.org/bitbucket/oopsen/nfs/tcpdump.bin
You may want to filter out the ssh packets. The only `interesting' thing to
me is a retransmission about half way through, but I don't know what I'm
looking for.
The NFS server is 10.1.203.204 and the client is 10.1.203.24.
Will
Hi Andros,
On Tue, Sep 23, 2014 at 04:25:58PM +0100, Will Deacon wrote:
> On Tue, Sep 23, 2014 at 04:08:36PM +0100, Weston Andros Adamson wrote:
> > On Sep 23, 2014, at 11:02 AM, Weston Andros Adamson <[email protected]> wrote:
> > > Wait a second - the whole point of this extra reference (that the
> > > WARN_ON_ONCE is related to) is to handle the pass off to commit lists.
> > >
> > > Maybe I’m just doing the wrong thing here with NFSv2!
> > >
> > > More soon.
> >
> > Actually, can you see if this is reproducible with NFSv3?
>
> Just tried that, and I'm unable to trigger the problem with NFSv3.
Any more ideas? I can run with NFSv3 instead, but it's a shame to leave
v2 broken.
Will
On Sep 23, 2014, at 10:59 AM, Weston Andros Adamson <[email protected]> wrote:
> On Sep 23, 2014, at 10:53 AM, Will Deacon <[email protected]> wrote:
>
>> On Tue, Sep 23, 2014 at 02:59:38PM +0100, Will Deacon wrote:
>>> On Tue, Sep 23, 2014 at 02:33:06PM +0100, Weston Andros Adamson wrote:
>>>> Any more info on how to reproduce this would be really great. Unfortunately I don?t
>>>> have access to an arm64 system.
>>>
>>> I've not spotted a pattern other than using 64k pages, yet. If I manage to
>>> get a reproducer, I'll let you know.
>>>
>>>> If it?s possible, could we get a packet trace around when this happens? This is pure
>>>> speculation, but this might have something to do the resend path - a commit fails
>>>> and all the requests on the commit list have to be resent.
>>>
>>> Sure, once I can reproduce it reliably, then I'll try to do that.
>>
>> Right, a bunch of DDing from /dev/zero over an ssh session triggers this
>> very quickly. I've put a binary tcpdump here:
>>
>> http://www.willdeacon.ukfsn.org/bitbucket/oopsen/nfs/tcpdump.bin
>>
>> You may want to filter out the ssh packets. The only `interesting' thing to
>> me is a retransmission about half way through, but I don't know what I'm
>> looking for.
>>
>> The NFS server is 10.1.203.204 and the client is 10.1.203.24.
>
> Thanks! You are using NFSv2, so there are no commits - that rules out my hunch.
Wait a second - the whole point of this extra reference (that the WARN_ON_ONCE is
related to) is to handle the pass off to commit lists.
Maybe I?m just doing the wrong thing here with NFSv2!
More soon.
-dros
On Sep 23, 2014, at 10:53 AM, Will Deacon <[email protected]> wrote:
> On Tue, Sep 23, 2014 at 02:59:38PM +0100, Will Deacon wrote:
>> On Tue, Sep 23, 2014 at 02:33:06PM +0100, Weston Andros Adamson wrote:
>>> Any more info on how to reproduce this would be really great. Unfortunately I don?t
>>> have access to an arm64 system.
>>
>> I've not spotted a pattern other than using 64k pages, yet. If I manage to
>> get a reproducer, I'll let you know.
>>
>>> If it?s possible, could we get a packet trace around when this happens? This is pure
>>> speculation, but this might have something to do the resend path - a commit fails
>>> and all the requests on the commit list have to be resent.
>>
>> Sure, once I can reproduce it reliably, then I'll try to do that.
>
> Right, a bunch of DDing from /dev/zero over an ssh session triggers this
> very quickly. I've put a binary tcpdump here:
>
> http://www.willdeacon.ukfsn.org/bitbucket/oopsen/nfs/tcpdump.bin
>
> You may want to filter out the ssh packets. The only `interesting' thing to
> me is a retransmission about half way through, but I don't know what I'm
> looking for.
>
> The NFS server is 10.1.203.204 and the client is 10.1.203.24.
Thanks! You are using NFSv2, so there are no commits - that rules out my hunch.
-dros
On Tue, Sep 23, 2014 at 04:08:36PM +0100, Weston Andros Adamson wrote:
> On Sep 23, 2014, at 11:02 AM, Weston Andros Adamson <[email protected]> wrote:
> > Wait a second - the whole point of this extra reference (that the
> > WARN_ON_ONCE is related to) is to handle the pass off to commit lists.
> >
> > Maybe I’m just doing the wrong thing here with NFSv2!
> >
> > More soon.
>
> Actually, can you see if this is reproducible with NFSv3?
Just tried that, and I'm unable to trigger the problem with NFSv3.
Will
On Tue, Sep 23, 2014 at 02:33:06PM +0100, Weston Andros Adamson wrote:
> On Sep 23, 2014, at 9:03 AM, Will Deacon <[email protected]> wrote:
> > I've been running into the following warning on an arm64 system running
> > 3.17-rc6 with 64k pages. I've been unable to reproduce with a smaller page
> > size (4k).
> >
> > I don't yet have a concrete reproducer, but I've seen it hit a few times
> > today just running a machine with an NFS root filesystem and using ssh.
> > The warning seems to happen in parallel on the two CPUs, but I'm pretty
> > confident that our test_and_clear_bit implementation has the relevant
> > atomic instructions and memory barriers.
> >
> > Any ideas?
>
> So it looks like we’re either calling nfs_inode_remove_request twice on a request,
> or somehow not grabbing the inode reference for some request that is in the async
> write path. It’s interesting that these come in pairs - that has to mean something!
Indeed. I have 6 CPUs on this system too, so it's not a per-cpu thing.
> Any more info on how to reproduce this would be really great. Unfortunately I don’t
> have access to an arm64 system.
I've not spotted a pattern other than using 64k pages, yet. If I manage to
get a reproducer, I'll let you know.
> If it’s possible, could we get a packet trace around when this happens? This is pure
> speculation, but this might have something to do the resend path - a commit fails
> and all the requests on the commit list have to be resent.
Sure, once I can reproduce it reliably, then I'll try to do that.
> Have you noticed any side effects from this? That WARN_ON_ONCE was added
> to sanity test the new page group code and we need to fix this, but I’m wondering
> if anything “bad” happens…
I've not noticed anything. In fact, this happened during an LTP run and I
didn't see any regressions in the test results.
Will
On Sep 25, 2014, at 1:15 PM, Will Deacon <[email protected]> wrote:
> Hi Andros,
>
> On Tue, Sep 23, 2014 at 04:25:58PM +0100, Will Deacon wrote:
>> On Tue, Sep 23, 2014 at 04:08:36PM +0100, Weston Andros Adamson wrote:
>>> On Sep 23, 2014, at 11:02 AM, Weston Andros Adamson <[email protected]> wrote:
>>>> Wait a second - the whole point of this extra reference (that the
>>>> WARN_ON_ONCE is related to) is to handle the pass off to commit lists.
>>>>
>>>> Maybe I?m just doing the wrong thing here with NFSv2!
>>>>
>>>> More soon.
>>>
>>> Actually, can you see if this is reproducible with NFSv3?
>>
>> Just tried that, and I'm unable to trigger the problem with NFSv3.
>
> Any more ideas? I can run with NFSv3 instead, but it's a shame to leave
> v2 broken.
Hi Will,
I do plan on looking at this more very soon, but since it?s v2 only and just warning
(and not crashing anything) it didn?t jump to the top of my list. It is only printing the
warnings, right? That?s no reason to switch things up ;)
It might be interesting to get some rpcdebug output around the time of the warning,
but I?m not sure it will be useful.
Since I cannot reproduce this, my next step is to inspect the code with an NFSv2
with 64k pages setup in mind.
-dros
Hey Will,
I?ve been very busy, but I haven?t forgotten about your bug report!
I think the WARN_ON_ONCE is just wrong, there are cases where the PG_INODE_REF
flag is legitimately not set. The flag is set so that sub requests can mimmic the parent
request?s reference count.
Could you please run the reproducer again, unmount, then check the contents of
/proc/fs/nfsfs/servers?
If it?s empty like example output below, then we know that requests are being properly
dereferenced.
# cat /proc/fs/nfsfs/servers
NV SERVER PORT USE HOSTNAME
#
If there are any servers still listed (I?m assuming this is the only mount on your client for
the test), then we have a problem.
-dros
On Sep 25, 2014, at 1:27 PM, Weston Andros Adamson <[email protected]> wrote:
> On Sep 25, 2014, at 1:15 PM, Will Deacon <[email protected]> wrote:
>
>> Hi Andros,
>>
>> On Tue, Sep 23, 2014 at 04:25:58PM +0100, Will Deacon wrote:
>>> On Tue, Sep 23, 2014 at 04:08:36PM +0100, Weston Andros Adamson wrote:
>>>> On Sep 23, 2014, at 11:02 AM, Weston Andros Adamson <[email protected]> wrote:
>>>>> Wait a second - the whole point of this extra reference (that the
>>>>> WARN_ON_ONCE is related to) is to handle the pass off to commit lists.
>>>>>
>>>>> Maybe I?m just doing the wrong thing here with NFSv2!
>>>>>
>>>>> More soon.
>>>>
>>>> Actually, can you see if this is reproducible with NFSv3?
>>>
>>> Just tried that, and I'm unable to trigger the problem with NFSv3.
>>
>> Any more ideas? I can run with NFSv3 instead, but it's a shame to leave
>> v2 broken.
>
> Hi Will,
>
> I do plan on looking at this more very soon, but since it?s v2 only and just warning
> (and not crashing anything) it didn?t jump to the top of my list. It is only printing the
> warnings, right? That?s no reason to switch things up ;)
>
> It might be interesting to get some rpcdebug output around the time of the warning,
> but I?m not sure it will be useful.
>
> Since I cannot reproduce this, my next step is to inspect the code with an NFSv2
> with 64k pages setup in mind.
>
> -dros
On Sat, Oct 11, 2014 at 02:32:29PM +0100, Weston Andros Adamson wrote:
> Hey Will,
Hi again, Andros,
> I’ve been very busy, but I haven’t forgotten about your bug report!
No problem, I've been busy too. I just checked with -rc1 and I can reproduce
the issue there too.
> I think the WARN_ON_ONCE is just wrong, there are cases where the
> PG_INODE_REF flag is legitimately not set. The flag is set so that sub
> requests can mimmic the parent request’s reference count.
>
> Could you please run the reproducer again, unmount, then check the contents of
> /proc/fs/nfsfs/servers?
Sure. I just tried this and that file is empty after unmounting.
Will
On Fri, Oct 31, 2014 at 02:49:13PM +0000, Weston Andros Adamson wrote:
> On Oct 20, 2014, at 9:57 AM, Will Deacon <[email protected]> wrote:
> > On Sat, Oct 11, 2014 at 02:32:29PM +0100, Weston Andros Adamson wrote:
> >> I’ve been very busy, but I haven’t forgotten about your bug report!
> >
> > No problem, I've been busy too. I just checked with -rc1 and I can reproduce
> > the issue there too.
> >
> >> I think the WARN_ON_ONCE is just wrong, there are cases where the
> >> PG_INODE_REF flag is legitimately not set. The flag is set so that sub
> >> requests can mimmic the parent request’s reference count.
> >>
> >> Could you please run the reproducer again, unmount, then check the contents of
> >> /proc/fs/nfsfs/servers?
> >
> > Sure. I just tried this and that file is empty after unmounting.
>
> Sorry for the delay (again) - I just got back from a two week holiday.
>
> This is good news! I think we can safely remove this WARN_ON_ONCE and call it a
> day… or maybe calling it a month is more accurate ;)
Great! Feel free to add my reported-by/tested-by on that patch.
Will
On Oct 20, 2014, at 9:57 AM, Will Deacon <[email protected]> wrote:
> On Sat, Oct 11, 2014 at 02:32:29PM +0100, Weston Andros Adamson wrote:
>> Hey Will,
>
> Hi again, Andros,
>
>> I?ve been very busy, but I haven?t forgotten about your bug report!
>
> No problem, I've been busy too. I just checked with -rc1 and I can reproduce
> the issue there too.
>
>> I think the WARN_ON_ONCE is just wrong, there are cases where the
>> PG_INODE_REF flag is legitimately not set. The flag is set so that sub
>> requests can mimmic the parent request?s reference count.
>>
>> Could you please run the reproducer again, unmount, then check the contents of
>> /proc/fs/nfsfs/servers?
>
> Sure. I just tried this and that file is empty after unmounting.
Sorry for the delay (again) - I just got back from a two week holiday.
This is good news! I think we can safely remove this WARN_ON_ONCE and call it a
day? or maybe calling it a month is more accurate ;)
-dros