fuse: trying to steal weird page

fuse: trying to steal weird page

[Nikolaus Rath]

Hello,

I have recently noticed that a FUSE filesystem regularly produces many
kernel messages like this:

[ 2333.009931] fuse: trying to steal weird page
[ 2333.009937] fuse:   page=00000000dd1750e3 index=2022240 flags=17ffffc0000097, count=1, mapcount=0, mapping=00000000125079ad
[ 2334.595835] fuse: trying to steal weird page
[ 2334.595841] fuse:   page=000000009e8626ac index=2052288 flags=17ffffc0000097, count=1, mapcount=0, mapping=00000000125079ad
[ 2334.983568] fuse: trying to steal weird page
[ 2334.983572] fuse:   page=0000000013fdd9e4 index=2059392 flags=17ffffc0000097, count=1, mapcount=0, mapping=00000000125079ad
[ 2335.979905] fuse: trying to steal weird page
[ 2335.979911] fuse:   page=00000000a7057848 index=2078588 flags=17ffffc0000097, count=1, mapcount=0, mapping=00000000125079ad

They do not seem to correlate with userspace errors, but I noticed that
there is no significant performance difference between libfuse using
splice, splice with SPLICE_MOVE, and not using splice. This is somewhat
unexpected, so maybe it is related to the kernel messages?

What are the implications of the above kernel message? Is there a way to
provide more debugging information?

(I have reported a similar issue before
(https://marc.info/?l=linux-mm&m=155290847909996&w=2) and the patch may
not be present in the kernel that I'm using. However, the previous time
the warning had a different set of flags and a null mapping, so I think
this one is different).

$ uname -a
Linux valve 5.3.0-46-generic #38-Ubuntu SMP Fri Mar 27 17:37:05 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux


Best,
-Nikolaus


-- 
GPG Fingerprint: ED31 791B 2C5C 1613 AF38 8B8A D113 FCAC 3C4E 599F

             »Time flies like an arrow, fruit flies like a Banana.«

Re: fuse: trying to steal weird page

[Nikolaus Rath]

On May 02 2020, Nikolaus Rath <Nikolaus@rath.org> wrote:
> Hello,
>
> I have recently noticed that a FUSE filesystem regularly produces many
> kernel messages like this:
>
> [ 2333.009931] fuse: trying to steal weird page
> [ 2333.009937] fuse: page=00000000dd1750e3 index=2022240 flags=17ffffc0000097, count=1,
> mapcount=0, mapping=00000000125079ad
> [ 2334.595835] fuse: trying to steal weird page
> [ 2334.595841] fuse: page=000000009e8626ac index=2052288 flags=17ffffc0000097, count=1,
> mapcount=0, mapping=00000000125079ad
> [ 2334.983568] fuse: trying to steal weird page
> [ 2334.983572] fuse: page=0000000013fdd9e4 index=2059392 flags=17ffffc0000097, count=1,
> mapcount=0, mapping=00000000125079ad
> [ 2335.979905] fuse: trying to steal weird page
> [ 2335.979911] fuse: page=00000000a7057848 index=2078588 flags=17ffffc0000097, count=1,
> mapcount=0, mapping=00000000125079ad
>
> They do not seem to correlate with userspace errors, but I noticed that
> there is no significant performance difference between libfuse using
> splice, splice with SPLICE_MOVE, and not using splice. This is somewhat
> unexpected, so maybe it is related to the kernel messages?
>
> What are the implications of the above kernel message? Is there a way to
> provide more debugging information?
>
> (I have reported a similar issue before
> (https://marc.info/?l=linux-mm&m=155290847909996&w=2) and the patch may
> not be present in the kernel that I'm using. However, the previous time
> the warning had a different set of flags and a null mapping, so I think
> this one is different).
>
> $ uname -a
> Linux valve 5.3.0-46-generic #38-Ubuntu SMP Fri Mar 27 17:37:05 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux


I have now reproduced this with a vanilla 5.6 kernel.

I also found that the "mapping" and "flags" parameters always have the
same values - even across different workloads and when re-mounting the
filesystem. The "page" parameter varies.


Best,
-Nikolaus

-- 
GPG Fingerprint: ED31 791B 2C5C 1613 AF38 8B8A D113 FCAC 3C4E 599F

             »Time flies like an arrow, fruit flies like a Banana.«

Re: fuse: trying to steal weird page

[Matthew Wilcox]

On Sat, May 02, 2020 at 08:52:48PM +0100, Nikolaus Rath wrote:
> On May 02 2020, Nikolaus Rath <Nikolaus@rath.org> wrote:
> > I have recently noticed that a FUSE filesystem regularly produces many
> > kernel messages like this:
> >
> > [ 2333.009931] fuse: trying to steal weird page
> > [ 2333.009937] fuse: page=00000000dd1750e3 index=2022240 flags=17ffffc0000097, count=1,
> > mapcount=0, mapping=00000000125079ad
...
> > What are the implications of the above kernel message? Is there a way to
> > provide more debugging information?

It'd be helpful to use the common debugging infrastructure which prints
more useful information:

+++ b/fs/fuse/dev.c
@@ -772,8 +772,7 @@ static int fuse_check_page(struct page *page)
               1 << PG_lru |
               1 << PG_active |
               1 << PG_reclaim))) {
-               pr_warn("trying to steal weird page\n");
-               pr_warn("  page=%p index=%li flags=%08lx, count=%i, mapcount=%i, mapping=%p\n", page, page->index, page->flags, page_count(page), page_mapcount(page), page->mapping);
+               dump_page(page, "fuse: trying to steal weird page");
                return 1;
        }
        return 0;

(whitespace damaged; if you can't make the equivalent change, let me
know and I'll send you a real patch)

Re: [fuse-devel] fuse: trying to steal weird page

[Nikolaus Rath]

On May 02 2020, Matthew Wilcox <willy@infradead.org> wrote:
> On Sat, May 02, 2020 at 08:52:48PM +0100, Nikolaus Rath wrote:
>> On May 02 2020, Nikolaus Rath <Nikolaus@rath.org> wrote:
>> > I have recently noticed that a FUSE filesystem regularly produces many
>> > kernel messages like this:
>> >
>> > [ 2333.009931] fuse: trying to steal weird page
>> > [ 2333.009937] fuse: page=00000000dd1750e3 index=2022240 flags=17ffffc0000097, count=1,
>> > mapcount=0, mapping=00000000125079ad
> ...
>> > What are the implications of the above kernel message? Is there a way to
>> > provide more debugging information?
>
> It'd be helpful to use the common debugging infrastructure which prints
> more useful information:
>
> +++ b/fs/fuse/dev.c
> @@ -772,8 +772,7 @@ static int fuse_check_page(struct page *page)
>                1 << PG_lru |
>                1 << PG_active |
>                1 << PG_reclaim))) {
> -               pr_warn("trying to steal weird page\n");
> -               pr_warn("  page=%p index=%li flags=%08lx, count=%i, mapcount=%i, mapping=%p\n", page, page->index, page->flags, page_count(page), page_mapcount(page), page->mapping);
> +               dump_page(page, "fuse: trying to steal weird page");
>                 return 1;
>         }
>         return 0;
>
> (whitespace damaged; if you can't make the equivalent change, let me
> know and I'll send you a real patch)

Here's what I got:

[  221.277260] page:ffffec4bbd639880 refcount:1 mapcount:0 mapping:0000000000000000 index:0xd9
[  221.277265] flags: 0x17ffffc0000097(locked|waiters|referenced|uptodate|lru)
[  221.277269] raw: 0017ffffc0000097 ffffec4bbd62f048 ffffec4bbd619308 0000000000000000
[  221.277271] raw: 00000000000000d9 0000000000000000 00000001ffffffff ffff9aec11beb000
[  221.277272] page dumped because: fuse: trying to steal weird page
[  221.277273] page->mem_cgroup:ffff9aec11beb000
[  221.601910] page:ffffec4bbd4b2dc0 refcount:1 mapcount:0 mapping:0000000000000000 index:0x1273
[  221.601915] flags: 0x17ffffc0000097(locked|waiters|referenced|uptodate|lru)
[  221.601919] raw: 0017ffffc0000097 ffffec4bbd51f488 ffffec4bbd4b2d48 0000000000000000
[  221.601921] raw: 0000000000001273 0000000000000000 00000001ffffffff ffff9aec11beb000
[  221.601922] page dumped because: fuse: trying to steal weird page
[  221.601923] page->mem_cgroup:ffff9aec11beb000
[  221.958699] page:ffffec4bbd424d80 refcount:1 mapcount:0 mapping:0000000000000000 index:0x38be
[  221.958703] flags: 0x17ffffc0000097(locked|waiters|referenced|uptodate|lru)
[  221.958707] raw: 0017ffffc0000097 ffffec4bbd424048 ffffec4bbd424d48 0000000000000000
[  221.958709] raw: 00000000000038be 0000000000000000 00000001ffffffff ffff9aec11beb000
[  221.958710] page dumped because: fuse: trying to steal weird page
[  221.958711] page->mem_cgroup:ffff9aec11beb000



Best,
-Nikolaus
-- 
GPG Fingerprint: ED31 791B 2C5C 1613 AF38 8B8A D113 FCAC 3C4E 599F

             »Time flies like an arrow, fruit flies like a Banana.«

Re: [fuse-devel] fuse: trying to steal weird page

[Matthew Wilcox]

On Sun, May 03, 2020 at 09:43:41AM +0100, Nikolaus Rath wrote:
> Here's what I got:
> 
> [  221.277260] page:ffffec4bbd639880 refcount:1 mapcount:0 mapping:0000000000000000 index:0xd9
> [  221.277265] flags: 0x17ffffc0000097(locked|waiters|referenced|uptodate|lru)
> [  221.277269] raw: 0017ffffc0000097 ffffec4bbd62f048 ffffec4bbd619308 0000000000000000
> [  221.277271] raw: 00000000000000d9 0000000000000000 00000001ffffffff ffff9aec11beb000
> [  221.277272] page dumped because: fuse: trying to steal weird page
> [  221.277273] page->mem_cgroup:ffff9aec11beb000

Great!  Here's the condition:

        if (page_mapcount(page) ||
            page->mapping != NULL ||
            page_count(page) != 1 ||
            (page->flags & PAGE_FLAGS_CHECK_AT_PREP &
             ~(1 << PG_locked |
               1 << PG_referenced |
               1 << PG_uptodate |
               1 << PG_lru |
               1 << PG_active |
               1 << PG_reclaim))) {

mapcount is 0, mapping is NULL, refcount is 1, so that's all fine.
flags has 'waiters' set, which is not in the allowed list.  I don't
know the internals of FUSE, so I don't know why that is.

Also, page_count() is unstable.  Unless there has been an RCU grace period
between when the page was freed and now, a speculative reference may exist
from the page cache.  So I would say this is a bad thing to check for.

Thanks for the swift provision of the debugging data!

Re: [fuse-devel] fuse: trying to steal weird page

[Gabriel Krisman Bertazi]

Matthew Wilcox <willy@infradead.org> writes:

> On Sun, May 03, 2020 at 09:43:41AM +0100, Nikolaus Rath wrote:
>> Here's what I got:
>> 
>> [  221.277260] page:ffffec4bbd639880 refcount:1 mapcount:0 mapping:0000000000000000 index:0xd9
>> [  221.277265] flags: 0x17ffffc0000097(locked|waiters|referenced|uptodate|lru)
>> [  221.277269] raw: 0017ffffc0000097 ffffec4bbd62f048 ffffec4bbd619308 0000000000000000
>> [  221.277271] raw: 00000000000000d9 0000000000000000 00000001ffffffff ffff9aec11beb000
>> [  221.277272] page dumped because: fuse: trying to steal weird page
>> [  221.277273] page->mem_cgroup:ffff9aec11beb000
>
> Great!  Here's the condition:
>
>         if (page_mapcount(page) ||
>             page->mapping != NULL ||
>             page_count(page) != 1 ||
>             (page->flags & PAGE_FLAGS_CHECK_AT_PREP &
>              ~(1 << PG_locked |
>                1 << PG_referenced |
>                1 << PG_uptodate |
>                1 << PG_lru |
>                1 << PG_active |
>                1 << PG_reclaim))) {
>
> mapcount is 0, mapping is NULL, refcount is 1, so that's all fine.
> flags has 'waiters' set, which is not in the allowed list.  I don't
> know the internals of FUSE, so I don't know why that is.
>

Hi

On the first message, Nikolaus sent the following line:

>> [ 2333.009937] fuse: page=00000000dd1750e3 index=2022240 flags=17ffffc0000097, count=1,
>> mapcount=0, mapping=00000000125079ad

It should be noted that on the second run, where we got the dump_page
log, it indeed had a null mapping, which is similar to what Nikolaus
asked on the previous thread he linked to, but looks like this wasn't
the case on at least some of the reproductions of the issue.  On the
line above, the condition that triggered the warning was page->mapping
!= NULL.  I don't know what to do with this information, though.



-- 
Gabriel Krisman Bertazi

Re: [fuse-devel] fuse: trying to steal weird page

[Matthew Wilcox]

On Sun, May 03, 2020 at 02:28:34PM -0400, Gabriel Krisman Bertazi wrote:
> Matthew Wilcox <willy@infradead.org> writes:
> > mapcount is 0, mapping is NULL, refcount is 1, so that's all fine.
> > flags has 'waiters' set, which is not in the allowed list.  I don't
> > know the internals of FUSE, so I don't know why that is.
> 
> Hi
> 
> On the first message, Nikolaus sent the following line:
> 
> >> [ 2333.009937] fuse: page=00000000dd1750e3 index=2022240 flags=17ffffc0000097, count=1,
> >> mapcount=0, mapping=00000000125079ad
> 
> It should be noted that on the second run, where we got the dump_page
> log, it indeed had a null mapping, which is similar to what Nikolaus
> asked on the previous thread he linked to, but looks like this wasn't
> the case on at least some of the reproductions of the issue.  On the
> line above, the condition that triggered the warning was page->mapping
> != NULL.  I don't know what to do with this information, though.

I don't see anything in upstream which will print "NULL" for a null
pointer passed to pointer().  ptr_to_id() doesn't check for NULL, nor
does __ptr_to_hashval().

I think we _should_, along with the ERR_PTR values and values less
than 4096.  But that patch isn't upstream.

Re: [fuse-devel] fuse: trying to steal weird page

[Nikolaus Rath]

On May 03 2020, Gabriel Krisman Bertazi <krisman@collabora.com> wrote:
> Matthew Wilcox <willy@infradead.org> writes:
>
>> On Sun, May 03, 2020 at 09:43:41AM +0100, Nikolaus Rath wrote:
>>> Here's what I got:
>>> 
>>> [  221.277260] page:ffffec4bbd639880 refcount:1 mapcount:0 mapping:0000000000000000 index:0xd9
>>> [  221.277265] flags: 0x17ffffc0000097(locked|waiters|referenced|uptodate|lru)
>>> [  221.277269] raw: 0017ffffc0000097 ffffec4bbd62f048 ffffec4bbd619308 0000000000000000
>>> [  221.277271] raw: 00000000000000d9 0000000000000000 00000001ffffffff ffff9aec11beb000
>>> [  221.277272] page dumped because: fuse: trying to steal weird page
>>> [  221.277273] page->mem_cgroup:ffff9aec11beb000
>>
>> Great!  Here's the condition:
>>
>>         if (page_mapcount(page) ||
>>             page->mapping != NULL ||
>>             page_count(page) != 1 ||
>>             (page->flags & PAGE_FLAGS_CHECK_AT_PREP &
>>              ~(1 << PG_locked |
>>                1 << PG_referenced |
>>                1 << PG_uptodate |
>>                1 << PG_lru |
>>                1 << PG_active |
>>                1 << PG_reclaim))) {
>>
>> mapcount is 0, mapping is NULL, refcount is 1, so that's all fine.
>> flags has 'waiters' set, which is not in the allowed list.  I don't
>> know the internals of FUSE, so I don't know why that is.
>>
>
> On the first message, Nikolaus sent the following line:
>
>>> [ 2333.009937] fuse: page=00000000dd1750e3 index=2022240 flags=17ffffc0000097, count=1,
>>> mapcount=0, mapping=00000000125079ad
>
> It should be noted that on the second run, where we got the dump_page
> log, it indeed had a null mapping, which is similar to what Nikolaus
> asked on the previous thread he linked to, but looks like this wasn't
> the case on at least some of the reproductions of the issue.  On the
> line above, the condition that triggered the warning was page->mapping
> != NULL.  I don't know what to do with this information, though.

Indeed, that's curious. I've modified the patch slightly to print both
the old and the new message to confirm. And indeed:

[  260.882873] fuse: trying to steal weird page
[  260.882879] fuse:   page=00000000813e7570 index=2010048 flags=17ffffc0000097, count=1, mapcount=0, mapping=0000000094844a11
[  260.882882] page:ffffe13431bcc000 refcount:1 mapcount:0 mapping:0000000000000000 index:0x1eabc0
[  260.882885] flags: 0x17ffffc0000097(locked|waiters|referenced|uptodate|lru)
[  260.882889] raw: 0017ffffc0000097 ffffe13431ca7c48 ffffe13431bcbfc8 0000000000000000
[  260.882891] raw: 00000000001eabc0 0000000000000000 00000001ffffffff ffff91fe31318000
[  260.882892] page dumped because: fuse: trying to steal weird page
[  260.882893] page->mem_cgroup:ffff91fe31318000
[  262.608438] fuse: trying to steal weird page
[  262.608444] fuse:   page=000000000c21d0c7 index=2040704 flags=17ffffc0000097, count=1, mapcount=0, mapping=0000000094844a11
[  262.608447] page:ffffe134319ebf80 refcount:1 mapcount:0 mapping:0000000000000000 index:0x1f2380
[  262.608450] flags: 0x17ffffc0000097(locked|waiters|referenced|uptodate|lru)
[  262.608455] raw: 0017ffffc0000097 ffffe134319e9fc8 ffffe134319ebf48 0000000000000000
[  262.608457] raw: 00000000001f2380 0000000000000000 00000001ffffffff ffff91fe31318000
[  262.608458] page dumped because: fuse: trying to steal weird page
[  262.608459] page->mem_cgroup:ffff91fe31318000
[  262.770209] fuse: trying to steal weird page
[  262.770215] fuse:   page=0000000018a813ac index=2045120 flags=17ffffc0000097, count=1, mapcount=0, mapping=0000000094844a11
[  262.770218] page:ffffe134319953c0 refcount:1 mapcount:0 mapping:0000000000000000 index:0x1f34c0
[  262.770221] flags: 0x17ffffc0000097(locked|waiters|referenced|uptodate|lru)
[  262.770225] raw: 0017ffffc0000097 ffffe134319ae788 ffffe13431995388 0000000000000000
[  262.770228] raw: 00000000001f34c0 0000000000000000 00000001ffffffff ffff91fe31318000
[  262.770229] page dumped because: fuse: trying to steal weird page
[  262.770230] page->mem_cgroup:ffff91fe31318000



Best,
-Nikolaus

-- 
GPG Fingerprint: ED31 791B 2C5C 1613 AF38 8B8A D113 FCAC 3C4E 599F

             »Time flies like an arrow, fruit flies like a Banana.«

Re: [fuse-devel] fuse: trying to steal weird page

[Vlastimil Babka]

On 5/3/20 10:25 PM, Nikolaus Rath wrote:
> On May 03 2020, Gabriel Krisman Bertazi <krisman@collabora.com> wrote:
>> Matthew Wilcox <willy@infradead.org> writes:
>>
>>> On Sun, May 03, 2020 at 09:43:41AM +0100, Nikolaus Rath wrote:
>>>> Here's what I got:
>>>> 
>>>> [  221.277260] page:ffffec4bbd639880 refcount:1 mapcount:0 mapping:0000000000000000 index:0xd9
>>>> [  221.277265] flags: 0x17ffffc0000097(locked|waiters|referenced|uptodate|lru)
>>>> [  221.277269] raw: 0017ffffc0000097 ffffec4bbd62f048 ffffec4bbd619308 0000000000000000
>>>> [  221.277271] raw: 00000000000000d9 0000000000000000 00000001ffffffff ffff9aec11beb000
>>>> [  221.277272] page dumped because: fuse: trying to steal weird page
>>>> [  221.277273] page->mem_cgroup:ffff9aec11beb000
>>>
>>> Great!  Here's the condition:
>>>
>>>         if (page_mapcount(page) ||
>>>             page->mapping != NULL ||
>>>             page_count(page) != 1 ||
>>>             (page->flags & PAGE_FLAGS_CHECK_AT_PREP &
>>>              ~(1 << PG_locked |
>>>                1 << PG_referenced |
>>>                1 << PG_uptodate |
>>>                1 << PG_lru |
>>>                1 << PG_active |
>>>                1 << PG_reclaim))) {
>>>
>>> mapcount is 0, mapping is NULL, refcount is 1, so that's all fine.
>>> flags has 'waiters' set, which is not in the allowed list.  I don't
>>> know the internals of FUSE, so I don't know why that is.
>>>
>>
>> On the first message, Nikolaus sent the following line:
>>
>>>> [ 2333.009937] fuse: page=00000000dd1750e3 index=2022240 flags=17ffffc0000097, count=1,
>>>> mapcount=0, mapping=00000000125079ad
>>
>> It should be noted that on the second run, where we got the dump_page
>> log, it indeed had a null mapping, which is similar to what Nikolaus
>> asked on the previous thread he linked to, but looks like this wasn't
>> the case on at least some of the reproductions of the issue.  On the
>> line above, the condition that triggered the warning was page->mapping
>> != NULL.  I don't know what to do with this information, though.
> 
> Indeed, that's curious. I've modified the patch slightly to print both
> the old and the new message to confirm. And indeed:
> 
> [  260.882873] fuse: trying to steal weird page
> [  260.882879] fuse:   page=00000000813e7570 index=2010048 flags=17ffffc0000097, count=1, mapcount=0, mapping=0000000094844a11

fuse_check_page() is using %p for these, so they are hashed (IIRC that means the
upper part is zeroed and the lower hashed)

> [  260.882882] page:ffffe13431bcc000 refcount:1 mapcount:0 mapping:0000000000000000 index:0x1eabc0

__dump_page() in 5.6 uses %px so they are unmodified. Thus it's really a NULL
pointer.

For extra fun, __dump_page() in 5.7 will also print page pointer unmodified, but
mapping will become hashed too.
Yeah it would be nice if NULLish values were treated specially, as
0000000094844a11 instead of NULL is really misleading. __dump_page() is fine
thanks to the raw dump, but other places perhaps not.

Re: [fuse-devel] fuse: trying to steal weird page

[Hugh Dickins]

On Sun, 3 May 2020, Matthew Wilcox wrote:
> On Sun, May 03, 2020 at 09:43:41AM +0100, Nikolaus Rath wrote:
> > Here's what I got:
> > 
> > [  221.277260] page:ffffec4bbd639880 refcount:1 mapcount:0 mapping:0000000000000000 index:0xd9
> > [  221.277265] flags: 0x17ffffc0000097(locked|waiters|referenced|uptodate|lru)
> > [  221.277269] raw: 0017ffffc0000097 ffffec4bbd62f048 ffffec4bbd619308 0000000000000000
> > [  221.277271] raw: 00000000000000d9 0000000000000000 00000001ffffffff ffff9aec11beb000
> > [  221.277272] page dumped because: fuse: trying to steal weird page
> > [  221.277273] page->mem_cgroup:ffff9aec11beb000
> 
> Great!  Here's the condition:
> 
>         if (page_mapcount(page) ||
>             page->mapping != NULL ||
>             page_count(page) != 1 ||
>             (page->flags & PAGE_FLAGS_CHECK_AT_PREP &
>              ~(1 << PG_locked |
>                1 << PG_referenced |
>                1 << PG_uptodate |
>                1 << PG_lru |
>                1 << PG_active |
>                1 << PG_reclaim))) {
> 
> mapcount is 0, mapping is NULL, refcount is 1, so that's all fine.
> flags has 'waiters' set, which is not in the allowed list.  I don't
> know the internals of FUSE, so I don't know why that is.

That list of PG_flags dates back to 2010: which 2016's 62906027091f
("mm: add PageWaiters indicating tasks are waiting for a page bit")
ought to have updated.  Though it's understandable that it did not:
surprising to find a list of PG_flags outside of mm/ and fs/proc/.
Just add PG_waiters to the list and the issue should go away.

> 
> Also, page_count() is unstable.

Agreed: fine to back out if page_count() is high,
but not good to issue a worrying warning about it.

> Unless there has been an RCU grace period
> between when the page was freed and now, a speculative reference may exist
> from the page cache.  So I would say this is a bad thing to check for.
> 
> Thanks for the swift provision of the debugging data!

Re: [fuse-devel] fuse: trying to steal weird page

[Miklos Szeredi]

On Sun, May 3, 2020 at 12:27 PM Matthew Wilcox <willy@infradead.org> wrote:
>
> On Sun, May 03, 2020 at 09:43:41AM +0100, Nikolaus Rath wrote:
> > Here's what I got:
> >
> > [  221.277260] page:ffffec4bbd639880 refcount:1 mapcount:0 mapping:0000000000000000 index:0xd9
> > [  221.277265] flags: 0x17ffffc0000097(locked|waiters|referenced|uptodate|lru)
> > [  221.277269] raw: 0017ffffc0000097 ffffec4bbd62f048 ffffec4bbd619308 0000000000000000
> > [  221.277271] raw: 00000000000000d9 0000000000000000 00000001ffffffff ffff9aec11beb000
> > [  221.277272] page dumped because: fuse: trying to steal weird page
> > [  221.277273] page->mem_cgroup:ffff9aec11beb000
>
> Great!  Here's the condition:
>
>         if (page_mapcount(page) ||
>             page->mapping != NULL ||
>             page_count(page) != 1 ||
>             (page->flags & PAGE_FLAGS_CHECK_AT_PREP &
>              ~(1 << PG_locked |
>                1 << PG_referenced |
>                1 << PG_uptodate |
>                1 << PG_lru |
>                1 << PG_active |
>                1 << PG_reclaim))) {
>
> mapcount is 0, mapping is NULL, refcount is 1, so that's all fine.
> flags has 'waiters' set, which is not in the allowed list.  I don't
> know the internals of FUSE, so I don't know why that is.
>
> Also, page_count() is unstable.  Unless there has been an RCU grace period
> between when the page was freed and now, a speculative reference may exist
> from the page cache.  So I would say this is a bad thing to check for.

page_cache_pipe_buf_steal() calls remove_mapping() which calls
page_ref_unfreeze(page, 1).  That sets the refcount to 1, right?

What am I missing?

Thanks,
Miklos

Re: [fuse-devel] fuse: trying to steal weird page

[Matthew Wilcox]

On Mon, May 18, 2020 at 02:45:02PM +0200, Miklos Szeredi wrote:
> On Sun, May 3, 2020 at 12:27 PM Matthew Wilcox <willy@infradead.org> wrote:
> >
> > On Sun, May 03, 2020 at 09:43:41AM +0100, Nikolaus Rath wrote:
> > > Here's what I got:
> > >
> > > [  221.277260] page:ffffec4bbd639880 refcount:1 mapcount:0 mapping:0000000000000000 index:0xd9
> > > [  221.277265] flags: 0x17ffffc0000097(locked|waiters|referenced|uptodate|lru)
> > > [  221.277269] raw: 0017ffffc0000097 ffffec4bbd62f048 ffffec4bbd619308 0000000000000000
> > > [  221.277271] raw: 00000000000000d9 0000000000000000 00000001ffffffff ffff9aec11beb000
> > > [  221.277272] page dumped because: fuse: trying to steal weird page
> > > [  221.277273] page->mem_cgroup:ffff9aec11beb000
> >
> > Great!  Here's the condition:
> >
> >         if (page_mapcount(page) ||
> >             page->mapping != NULL ||
> >             page_count(page) != 1 ||
> >             (page->flags & PAGE_FLAGS_CHECK_AT_PREP &
> >              ~(1 << PG_locked |
> >                1 << PG_referenced |
> >                1 << PG_uptodate |
> >                1 << PG_lru |
> >                1 << PG_active |
> >                1 << PG_reclaim))) {
> >
> > mapcount is 0, mapping is NULL, refcount is 1, so that's all fine.
> > flags has 'waiters' set, which is not in the allowed list.  I don't
> > know the internals of FUSE, so I don't know why that is.
> >
> > Also, page_count() is unstable.  Unless there has been an RCU grace period
> > between when the page was freed and now, a speculative reference may exist
> > from the page cache.  So I would say this is a bad thing to check for.
> 
> page_cache_pipe_buf_steal() calls remove_mapping() which calls
> page_ref_unfreeze(page, 1).  That sets the refcount to 1, right?
> 
> What am I missing?

find_get_entry() calling page_cache_get_speculative().

In a previous allocation, this page belonged to the page cache.  Then it
was freed, but another thread is in the middle of a page cache lookup and
has already loaded the pointer.  It is now delayed by a few clock ticks.

Now the page is allocated to FUSE, which calls page_ref_unfreeze().
And then the refcount gets bumped to 2 by page_cache_get_speculative().
find_get_entry() calls xas_reload() and discovers this page is no longer
at that index, so it calls put_page(), but in that narrow window, FUSE
checks the refcount and finds it's not 1.

Monumentally unlikely, of course, so you've probably never seen it,
but multiply by the hundreds of millions of devices running Linux,
and somebody will hit it someday.

Re: [fuse-devel] fuse: trying to steal weird page

[Miklos Szeredi]

On Mon, May 18, 2020 at 4:48 PM Matthew Wilcox <willy@infradead.org> wrote:
>
> On Mon, May 18, 2020 at 02:45:02PM +0200, Miklos Szeredi wrote:

> > page_cache_pipe_buf_steal() calls remove_mapping() which calls
> > page_ref_unfreeze(page, 1).  That sets the refcount to 1, right?
> >
> > What am I missing?
>
> find_get_entry() calling page_cache_get_speculative().
>
> In a previous allocation, this page belonged to the page cache.  Then it
> was freed, but another thread is in the middle of a page cache lookup and
> has already loaded the pointer.  It is now delayed by a few clock ticks.
>
> Now the page is allocated to FUSE, which calls page_ref_unfreeze().
> And then the refcount gets bumped to 2 by page_cache_get_speculative().
> find_get_entry() calls xas_reload() and discovers this page is no longer
> at that index, so it calls put_page(), but in that narrow window, FUSE
> checks the refcount and finds it's not 1.

What if that page_cache_get_speculative() happens just before
page_ref_unfreeze()?  The speculative reference would be lost and on
put_page() the page would be freed, even though fuse is still holding
the pointer.

Thanks,
Miklos

Re: [fuse-devel] fuse: trying to steal weird page

[Matthew Wilcox]

On Mon, May 18, 2020 at 04:58:05PM +0200, Miklos Szeredi wrote:
> On Mon, May 18, 2020 at 4:48 PM Matthew Wilcox <willy@infradead.org> wrote:
> >
> > On Mon, May 18, 2020 at 02:45:02PM +0200, Miklos Szeredi wrote:
> 
> > > page_cache_pipe_buf_steal() calls remove_mapping() which calls
> > > page_ref_unfreeze(page, 1).  That sets the refcount to 1, right?
> > >
> > > What am I missing?
> >
> > find_get_entry() calling page_cache_get_speculative().
> >
> > In a previous allocation, this page belonged to the page cache.  Then it
> > was freed, but another thread is in the middle of a page cache lookup and
> > has already loaded the pointer.  It is now delayed by a few clock ticks.
> >
> > Now the page is allocated to FUSE, which calls page_ref_unfreeze().
> > And then the refcount gets bumped to 2 by page_cache_get_speculative().
> > find_get_entry() calls xas_reload() and discovers this page is no longer
> > at that index, so it calls put_page(), but in that narrow window, FUSE
> > checks the refcount and finds it's not 1.
> 
> What if that page_cache_get_speculative() happens just before
> page_ref_unfreeze()?  The speculative reference would be lost and on
> put_page() the page would be freed, even though fuse is still holding
> the pointer.

static inline void page_ref_unfreeze(struct page *page, int count)
{
        VM_BUG_ON_PAGE(page_count(page) != 0, page);
        VM_BUG_ON(count == 0);

        atomic_set_release(&page->_refcount, count);

static inline int __page_cache_add_speculative(struct page *page, int count)
{
        if (unlikely(!page_ref_add_unless(page, count, 0))) {
                return 0;

Re: [fuse-devel] fuse: trying to steal weird page

[Nikolaus Rath]

[ Moving fuse-devel and linux-fsdevel to Bcc ]

Hello linux-mm people,

I am posting this here as advised by Miklos (see below). In short, I
have a workload that reliably produces kernel messages of the form:

[ 2562.773181] fuse: trying to steal weird page
[ 2562.773187] page=<something> index=<something> flags=17ffffc00000ad, count=1, mapcount=0, mapping= (null)

What are the implications of this message? Is something activelly going
wrong (aka do I need to worry about data integrity)?

Is there something I can do to help debugging (and hopefully fixing)
this?

This is with kernel 4.18 (from Ubuntu cosmic).

Best,
-Nikolaus


On Feb 26 2019, Miklos Szeredi <miklos@szeredi.hu> wrote:
> On Tue, Feb 26, 2019 at 1:57 PM Miklos Szeredi <miklos@szeredi.hu> wrote:
>>
>> On Mon, Feb 25, 2019 at 10:41 PM Nikolaus Rath <Nikolaus@rath.org> wrote:
>> >
>> > On Feb 12 2019, Nikolaus Rath <Nikolaus@rath.org> wrote:
>> > > On Feb 12 2019, Miklos Szeredi <miklos@szeredi.hu> wrote:
>> > >> On Sun, Feb 10, 2019 at 11:05 PM Nikolaus Rath <Nikolaus@rath.org> wrote:
>> > >>
>> > >>> Bad news. I can now reliably reproduce the issue again.
>> > >>
>> > >> A reliable reproducer is always good news.   Are the messages exactly
>> > >> the same as last time (value of flags, etc)?
>> > >
>> > > The flags, count, mapcount and mapping values are always the same. The
>> > > page and index is varying. So the general format is:
>> > >
>> > > [ 2562.773181] fuse: trying to steal weird page
>> > > [ 2562.773187] page=<something> index=<something>
>> > > flags=17ffffc00000ad, count=1, mapcount=0, mapping= (null)
>> >
>> > Is there anything else I can do to help debugging this?
>>
>> Could you please try the attached patch?
>
> Looking more, it's very unlikely to help.  remove_mapping() should
> already ensure that the page count is 1.
>
> I think this bug report needs to be forwarded to the
> <linux-mm@kvack.org> mailing list as this appears to be  a race
> somewhere in the memory management subsystem and fuse is only making
> it visible due to its sanity checking in the page stealing code.
>
> Thanks,
> Miklos
>
>
> -- 
> fuse-devel mailing list
> To unsubscribe or subscribe, visit https://lists.sourceforge.net/lists/listinfo/fuse-devel


-- 
GPG Fingerprint: ED31 791B 2C5C 1613 AF38 8B8A D113 FCAC 3C4E 599F

             »Time flies like an arrow, fruit flies like a Banana.«

Re: [fuse-devel] fuse: trying to steal weird page

[Miklos Szeredi]

On Tue, Feb 26, 2019 at 9:35 PM Nikolaus Rath <Nikolaus@rath.org> wrote:
>
> [ Moving fuse-devel and linux-fsdevel to Bcc ]
>
> Hello linux-mm people,
>
> I am posting this here as advised by Miklos (see below). In short, I
> have a workload that reliably produces kernel messages of the form:
>
> [ 2562.773181] fuse: trying to steal weird page
> [ 2562.773187] page=<something> index=<something> flags=17ffffc00000ad, count=1, mapcount=0, mapping= (null)
>
> What are the implications of this message? Is something activelly going
> wrong (aka do I need to worry about data integrity)?

Fuse is careful and basically just falls back on page copy, so it
definitely shouldn't affect data integrity.

The more interesting question is: how can page_cache_pipe_buf_steal()
return a dirty page?  The logic in remove_mapping() should prevent
that, but something is apparently slipping through...

>
> Is there something I can do to help debugging (and hopefully fixing)
> this?
>
> This is with kernel 4.18 (from Ubuntu cosmic).

One thought: have you tried reproducing with a recent vanilla
(non-ubuntu) kernel?

Thanks,
Miklos


>
> Best,
> -Nikolaus
>
>
> On Feb 26 2019, Miklos Szeredi <miklos@szeredi.hu> wrote:
> > On Tue, Feb 26, 2019 at 1:57 PM Miklos Szeredi <miklos@szeredi.hu> wrote:
> >>
> >> On Mon, Feb 25, 2019 at 10:41 PM Nikolaus Rath <Nikolaus@rath.org> wrote:
> >> >
> >> > On Feb 12 2019, Nikolaus Rath <Nikolaus@rath.org> wrote:
> >> > > On Feb 12 2019, Miklos Szeredi <miklos@szeredi.hu> wrote:
> >> > >> On Sun, Feb 10, 2019 at 11:05 PM Nikolaus Rath <Nikolaus@rath.org> wrote:
> >> > >>
> >> > >>> Bad news. I can now reliably reproduce the issue again.
> >> > >>
> >> > >> A reliable reproducer is always good news.   Are the messages exactly
> >> > >> the same as last time (value of flags, etc)?
> >> > >
> >> > > The flags, count, mapcount and mapping values are always the same. The
> >> > > page and index is varying. So the general format is:
> >> > >
> >> > > [ 2562.773181] fuse: trying to steal weird page
> >> > > [ 2562.773187] page=<something> index=<something>
> >> > > flags=17ffffc00000ad, count=1, mapcount=0, mapping= (null)
> >> >
> >> > Is there anything else I can do to help debugging this?
> >>
> >> Could you please try the attached patch?
> >
> > Looking more, it's very unlikely to help.  remove_mapping() should
> > already ensure that the page count is 1.
> >
> > I think this bug report needs to be forwarded to the
> > <linux-mm@kvack.org> mailing list as this appears to be  a race
> > somewhere in the memory management subsystem and fuse is only making
> > it visible due to its sanity checking in the page stealing code.
> >
> > Thanks,
> > Miklos
> >
> >
> > --
> > fuse-devel mailing list
> > To unsubscribe or subscribe, visit https://lists.sourceforge.net/lists/listinfo/fuse-devel
>
>
> --
> GPG Fingerprint: ED31 791B 2C5C 1613 AF38 8B8A D113 FCAC 3C4E 599F
>
>              »Time flies like an arrow, fruit flies like a Banana.«

Re: [fuse-devel] fuse: trying to steal weird page

[Nikolaus Rath]

On Feb 26 2019, Miklos Szeredi <miklos@szeredi.hu> wrote:
> On Tue, Feb 26, 2019 at 9:35 PM Nikolaus Rath <Nikolaus@rath.org> wrote:
>>
>> [ Moving fuse-devel and linux-fsdevel to Bcc ]
>>
>> Hello linux-mm people,
>>
>> I am posting this here as advised by Miklos (see below). In short, I
>> have a workload that reliably produces kernel messages of the form:
>>
>> [ 2562.773181] fuse: trying to steal weird page
>> [ 2562.773187] page=<something> index=<something> flags=17ffffc00000ad, count=1, mapcount=0, mapping= (null)
>>
>> What are the implications of this message? Is something activelly going
>> wrong (aka do I need to worry about data integrity)?
>
> Fuse is careful and basically just falls back on page copy, so it
> definitely shouldn't affect data integrity.
>
> The more interesting question is: how can page_cache_pipe_buf_steal()
> return a dirty page?  The logic in remove_mapping() should prevent
> that, but something is apparently slipping through...
>
>>
>> Is there something I can do to help debugging (and hopefully fixing)
>> this?
>>
>> This is with kernel 4.18 (from Ubuntu cosmic).
>
> One thought: have you tried reproducing with a recent vanilla
> (non-ubuntu) kernel?

Yes, I can reproduce with e.g. 5.0.0-050000rc8 (from
https://kernel.ubuntu.com/~kernel-ppa/mainline/v5.0-rc8/). However, here
the flag value is different:

[  278.183571] fuse: trying to steal weird page
[  278.183576]   page=000000000aab208c index=14944 flags=17ffffc0000097, count=1, mapcount=0, mapping=          (null)

(but still the same across all messages observed with this kernel so
far).


Best,
-Nikolaus


-- 
GPG Fingerprint: ED31 791B 2C5C 1613 AF38 8B8A D113 FCAC 3C4E 599F

             »Time flies like an arrow, fruit flies like a Banana.«

Re: [fuse-devel] fuse: trying to steal weird page

[Miklos Szeredi]

[-- Attachment #1: Type: text/plain, Size: 2091 bytes --]

On Fri, Mar 1, 2019 at 9:40 PM Nikolaus Rath <Nikolaus@rath.org> wrote:
>
> On Feb 26 2019, Miklos Szeredi <miklos@szeredi.hu> wrote:
> > On Tue, Feb 26, 2019 at 9:35 PM Nikolaus Rath <Nikolaus@rath.org> wrote:
> >>
> >> [ Moving fuse-devel and linux-fsdevel to Bcc ]
> >>
> >> Hello linux-mm people,
> >>
> >> I am posting this here as advised by Miklos (see below). In short, I
> >> have a workload that reliably produces kernel messages of the form:
> >>
> >> [ 2562.773181] fuse: trying to steal weird page
> >> [ 2562.773187] page=<something> index=<something> flags=17ffffc00000ad, count=1, mapcount=0, mapping= (null)
> >>
> >> What are the implications of this message? Is something activelly going
> >> wrong (aka do I need to worry about data integrity)?
> >
> > Fuse is careful and basically just falls back on page copy, so it
> > definitely shouldn't affect data integrity.
> >
> > The more interesting question is: how can page_cache_pipe_buf_steal()
> > return a dirty page?  The logic in remove_mapping() should prevent
> > that, but something is apparently slipping through...
> >
> >>
> >> Is there something I can do to help debugging (and hopefully fixing)
> >> this?
> >>
> >> This is with kernel 4.18 (from Ubuntu cosmic).
> >
> > One thought: have you tried reproducing with a recent vanilla
> > (non-ubuntu) kernel?
>
> Yes, I can reproduce with e.g. 5.0.0-050000rc8 (from
> https://kernel.ubuntu.com/~kernel-ppa/mainline/v5.0-rc8/). However, here
> the flag value is different:
>
> [  278.183571] fuse: trying to steal weird page
> [  278.183576]   page=000000000aab208c index=14944 flags=17ffffc0000097, count=1, mapcount=0, mapping=          (null)
>
> (but still the same across all messages observed with this kernel so
> far).

Ah, so it's just the PG_waiters flag that is triggering the "weird
page" message.   And it looks like it's okay if PG_waiters remains
set, at least that's what I infer from the comments in
wake_up_page_bit().  Patch attached.

I'm not sure about the Ubuntu one, you should try filing a bug report
with them, I think.

Thanks,
Miklos

[-- Attachment #2: fuse-allow-pg_waiters-in-stolen-patch.patch --]
[-- Type: text/x-patch, Size: 567 bytes --]

diff --git a/fs/fuse/dev.c b/fs/fuse/dev.c
index 8a63e52785e9..769605cdf2bd 100644
--- a/fs/fuse/dev.c
+++ b/fs/fuse/dev.c
@@ -905,6 +905,7 @@ static int fuse_check_page(struct page *page)
 	       1 << PG_uptodate |
 	       1 << PG_lru |
 	       1 << PG_active |
+	       1 << PG_waiters |
 	       1 << PG_reclaim))) {
 		printk(KERN_WARNING "fuse: trying to steal weird page\n");
 		printk(KERN_WARNING "  page=%p index=%li flags=%08lx, count=%i, mapcount=%i, mapping=%p\n", page, page->index, page->flags, page_count(page), page_mapcount(page), page->mapping);