Skip to contentSkip to conversation

mm: shmem: freeing mlocked page

DISCUSSION Sasha Levin 4 participants 10 messages Nov 7, 2014 – Dec 10, 2014 Memory management

lore
Share & tools
lore

Sasha Levin

author
#0 lore raw

Hi all,

While fuzzing with trinity inside a KVM tools guest running the latest -next kernel, I've stumbled on the following spew:

[ 1441.564471] BUG: Bad page state in process trinity-c612  pfn:12593a
[ 1441.564476] page:ffffea0006e175c0 count:0 mapcount:0 mapping:          (null) index:
0x49
[ 1441.564488] flags: 0xafffff8028000c(referenced|uptodate|swapbacked|mlocked)
[ 1441.564491] page dumped because: PAGE_FLAGS_CHECK_AT_FREE flag(s) set
[ 1441.564493] bad because of flags:
[ 1441.564498] flags: 0x200000(mlocked)
[ 1441.564503] Modules linked in:
[ 1441.564511] CPU: 2 PID: 11657 Comm: trinity-c612 Not tainted 3.18.0-rc3-next-20141106-sasha-00054-g09b7ccf-dirty #1447
[ 1441.564519]  0000000000000000 0000000000000000 1ffffffff3b44e48 ffff8805c969b868
[ 1441.564526]  ffffffff9c085024 0000000000000000 ffffea0006e175c0 ffff8805c969b898
[ 1441.564532]  ffffffff925fd0a1 ffffea0006e17628 dfffe90000000000 0000000000000000
[ 1441.564534] Call Trace:
[ 1441.568496] dump_stack (lib/dump_stack.c:52)
[ 1441.568516] bad_page (mm/page_alloc.c:338)
[ 1441.568523] free_pages_prepare (mm/page_alloc.c:649 mm/page_alloc.c:755)
[ 1441.568531] free_hot_cold_page (mm/page_alloc.c:1436)
[ 1441.568541] free_hot_cold_page_list (mm/page_alloc.c:1482 (discriminator 3))
[ 1441.568555] release_pages (mm/swap.c:961)
[ 1441.568566] __pagevec_release (include/linux/pagevec.h:44 mm/swap.c:978)
[ 1441.568579] shmem_undo_range (include/linux/pagevec.h:69 mm/shmem.c:451)
[ 1441.568591] shmem_truncate_range (mm/shmem.c:546)
[ 1441.568599] shmem_fallocate (include/linux/spinlock.h:309 mm/shmem.c:2092)
[ 1441.568612] ? __sb_start_write (fs/super.c:1208)
[ 1441.568622] ? __sb_start_write (fs/super.c:1208)
[ 1441.568633] do_fallocate (fs/open.c:297)
[ 1441.568648] SyS_madvise (mm/madvise.c:332 mm/madvise.c:381 mm/madvise.c:531 mm/madvise.c:462)
[ 1441.568660] ? syscall_trace_enter_phase1 (include/linux/context_tracking.h:27 arch/x86/kernel/ptrace.c:1486)
[ 1441.568672] tracesys_phase2 (arch/x86/kernel/entry_64.S:529)

I'm slightly confused here, because the page is mapcount==0, not LOCKED but still MLOCKED...

Thanks,
Sasha

author
#1 lore raw
Quoted 35 lines · Sasha Levin

Hi all,

While fuzzing with trinity inside a KVM tools guest running the latest -next kernel, I've stumbled on the following spew:

[ 1441.564471] BUG: Bad page state in process trinity-c612  pfn:12593a
[ 1441.564476] page:ffffea0006e175c0 count:0 mapcount:0 mapping:          (null) index:
0x49
[ 1441.564488] flags: 0xafffff8028000c(referenced|uptodate|swapbacked|mlocked)
[ 1441.564491] page dumped because: PAGE_FLAGS_CHECK_AT_FREE flag(s) set
[ 1441.564493] bad because of flags:
[ 1441.564498] flags: 0x200000(mlocked)
[ 1441.564503] Modules linked in:
[ 1441.564511] CPU: 2 PID: 11657 Comm: trinity-c612 Not tainted 3.18.0-rc3-next-20141106-sasha-00054-g09b7ccf-dirty #1447
[ 1441.564519]  0000000000000000 0000000000000000 1ffffffff3b44e48 ffff8805c969b868
[ 1441.564526]  ffffffff9c085024 0000000000000000 ffffea0006e175c0 ffff8805c969b898
[ 1441.564532]  ffffffff925fd0a1 ffffea0006e17628 dfffe90000000000 0000000000000000
[ 1441.564534] Call Trace:
[ 1441.568496] dump_stack (lib/dump_stack.c:52)
[ 1441.568516] bad_page (mm/page_alloc.c:338)
[ 1441.568523] free_pages_prepare (mm/page_alloc.c:649 mm/page_alloc.c:755)
[ 1441.568531] free_hot_cold_page (mm/page_alloc.c:1436)
[ 1441.568541] free_hot_cold_page_list (mm/page_alloc.c:1482 (discriminator 3))
[ 1441.568555] release_pages (mm/swap.c:961)
[ 1441.568566] __pagevec_release (include/linux/pagevec.h:44 mm/swap.c:978)
[ 1441.568579] shmem_undo_range (include/linux/pagevec.h:69 mm/shmem.c:451)
[ 1441.568591] shmem_truncate_range (mm/shmem.c:546)
[ 1441.568599] shmem_fallocate (include/linux/spinlock.h:309 mm/shmem.c:2092)
[ 1441.568612] ? __sb_start_write (fs/super.c:1208)
[ 1441.568622] ? __sb_start_write (fs/super.c:1208)
[ 1441.568633] do_fallocate (fs/open.c:297)
[ 1441.568648] SyS_madvise (mm/madvise.c:332 mm/madvise.c:381 mm/madvise.c:531 mm/madvise.c:462)
[ 1441.568660] ? syscall_trace_enter_phase1 (include/linux/context_tracking.h:27 arch/x86/kernel/ptrace.c:1486)
[ 1441.568672] tracesys_phase2 (arch/x86/kernel/entry_64.S:529)
Quoted 1 line

I'm slightly confused here, because the page is mapcount==0, not LOCKED but still MLOCKED...

So I got this as well:

[ 1026.988043] BUG: Bad page state in process trinity-c374  pfn:23f70
[ 1026.989684] page:ffffea0000b3d300 count:0 mapcount:0 mapping:          (null) index:0x5b
[ 1026.991151] flags: 0x1fffff8028000c(referenced|uptodate|swapbacked|mlocked)
[ 1026.992410] page dumped because: PAGE_FLAGS_CHECK_AT_FREE flag(s) set
[ 1026.993479] bad because of flags:
[ 1026.994125] flags: 0x200000(mlocked)
[ 1026.994816] Modules linked in:
[ 1026.995378] CPU: 7 PID: 7879 Comm: trinity-c374 Not tainted 3.18.0-rc4-next-20141113-sasha-00047-gd1763ce-dirty #1455
[ 1026.996123] FAULT_INJECTION: forcing a failure.
[ 1026.996123] name failslab, interval 100, probability 30, space 0, times -1
[ 1026.999050]  0000000000000000 0000000000000000 0000000000b3d300 ffff88061295bbd8
[ 1027.000676]  ffffffff92f71097 0000000000000000 ffffea0000b3d300 ffff88061295bc08
[ 1027.002020]  ffffffff8197ef7a ffffea0000b3d300 ffffffff942dd148 dfffe90000000000
[ 1027.003359] Call Trace:
[ 1027.003831] dump_stack (lib/dump_stack.c:52)
[ 1027.004725] bad_page (mm/page_alloc.c:338)
[ 1027.005623] free_pages_prepare (mm/page_alloc.c:657 mm/page_alloc.c:763)
[ 1027.006761] free_hot_cold_page (mm/page_alloc.c:1438)
[ 1027.007772] ? __page_cache_release (mm/swap.c:66)
[ 1027.008815] put_page (mm/swap.c:270)
[ 1027.009665] page_cache_pipe_buf_release (fs/splice.c:93)
[ 1027.010888] __splice_from_pipe (fs/splice.c:784 fs/splice.c:886)
[ 1027.011917] ? might_fault (./arch/x86/include/asm/current.h:14 mm/memory.c:3734)
[ 1027.012856] ? pipe_lock (fs/pipe.c:69)
[ 1027.013728] ? write_pipe_buf (fs/splice.c:1534)
[ 1027.014756] vmsplice_to_user (fs/splice.c:1574)
[ 1027.015725] ? rcu_read_lock_held (kernel/rcu/update.c:169)
[ 1027.016757] ? __fget_light (include/linux/fdtable.h:80 fs/file.c:684)
[ 1027.017782] SyS_vmsplice (fs/splice.c:1656 fs/splice.c:1639)
[ 1027.018863] tracesys_phase2 (arch/x86/kernel/entry_64.S:529)

Which makes me suspect I blamed shmem for nothing.

Thanks,
Sasha

maintainer
#2 lore raw
Quoted 7 lines · On Fri, 14 Nov 2014 09:39:40 -0500 Sasha Levin <[email protected]> wrote:
[ 1026.988043] BUG: Bad page state in process trinity-c374  pfn:23f70
[ 1026.989684] page:ffffea0000b3d300 count:0 mapcount:0 mapping:          (null) index:0x5b
[ 1026.991151] flags: 0x1fffff8028000c(referenced|uptodate|swapbacked|mlocked)
[ 1026.992410] page dumped because: PAGE_FLAGS_CHECK_AT_FREE flag(s) set
[ 1026.993479] bad because of flags:
[ 1026.994125] flags: 0x200000(mlocked)

Gee that new page dumping code is nice!

Quoted 16 lines
[ 1026.994816] Modules linked in:
[ 1026.995378] CPU: 7 PID: 7879 Comm: trinity-c374 Not tainted 3.18.0-rc4-next-20141113-sasha-00047-gd1763ce-dirty #1455
[ 1026.996123] FAULT_INJECTION: forcing a failure.
[ 1026.996123] name failslab, interval 100, probability 30, space 0, times -1
[ 1026.999050]  0000000000000000 0000000000000000 0000000000b3d300 ffff88061295bbd8
[ 1027.000676]  ffffffff92f71097 0000000000000000 ffffea0000b3d300 ffff88061295bc08
[ 1027.002020]  ffffffff8197ef7a ffffea0000b3d300 ffffffff942dd148 dfffe90000000000
[ 1027.003359] Call Trace:
[ 1027.003831] dump_stack (lib/dump_stack.c:52)
[ 1027.004725] bad_page (mm/page_alloc.c:338)
[ 1027.005623] free_pages_prepare (mm/page_alloc.c:657 mm/page_alloc.c:763)
[ 1027.006761] free_hot_cold_page (mm/page_alloc.c:1438)
[ 1027.007772] ? __page_cache_release (mm/swap.c:66)
[ 1027.008815] put_page (mm/swap.c:270)
[ 1027.009665] page_cache_pipe_buf_release (fs/splice.c:93)
[ 1027.010888] __splice_from_pipe (fs/splice.c:784 fs/splice.c:886)
Quoted 9 lines
[ 1027.011917] ? might_fault (./arch/x86/include/asm/current.h:14 mm/memory.c:3734)
[ 1027.012856] ? pipe_lock (fs/pipe.c:69)
[ 1027.013728] ? write_pipe_buf (fs/splice.c:1534)
[ 1027.014756] vmsplice_to_user (fs/splice.c:1574)
[ 1027.015725] ? rcu_read_lock_held (kernel/rcu/update.c:169)
[ 1027.016757] ? __fget_light (include/linux/fdtable.h:80 fs/file.c:684)
[ 1027.017782] SyS_vmsplice (fs/splice.c:1656 fs/splice.c:1639)
[ 1027.018863] tracesys_phase2 (arch/x86/kernel/entry_64.S:529)

So what happened here? Userspace fed some mlocked memory into splice() and then, while splice() was running, userspace dropped its reference to the memory, leaving splice() with the last reference. Yet somehow, that page was still marked as being mlocked. I wouldn't expect the kernel to permit userspace to drop its reference to the memory without first clearing the mlocked state.

Is it possible to work out from trinity sources what the exact sequence was? Which syscalls are being used, for example?

--
To unsubscribe, send a message with 'unsubscribe linux-mm' in the body to [email protected]. For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"[email protected]"> [email protected] </a>

author
#3 lore raw
Quoted 45 lines · Andrew Morton
Quoted 7 lines · On Fri, 14 Nov 2014 09:39:40 -0500 Sasha Levin <[email protected]> wrote:
[ 1026.988043] BUG: Bad page state in process trinity-c374  pfn:23f70
[ 1026.989684] page:ffffea0000b3d300 count:0 mapcount:0 mapping:          (null) index:0x5b
[ 1026.991151] flags: 0x1fffff8028000c(referenced|uptodate|swapbacked|mlocked)
[ 1026.992410] page dumped because: PAGE_FLAGS_CHECK_AT_FREE flag(s) set
[ 1026.993479] bad because of flags:
[ 1026.994125] flags: 0x200000(mlocked)

Gee that new page dumping code is nice!

Quoted 16 lines
[ 1026.994816] Modules linked in:
[ 1026.995378] CPU: 7 PID: 7879 Comm: trinity-c374 Not tainted 3.18.0-rc4-next-20141113-sasha-00047-gd1763ce-dirty #1455
[ 1026.996123] FAULT_INJECTION: forcing a failure.
[ 1026.996123] name failslab, interval 100, probability 30, space 0, times -1
[ 1026.999050]  0000000000000000 0000000000000000 0000000000b3d300 ffff88061295bbd8
[ 1027.000676]  ffffffff92f71097 0000000000000000 ffffea0000b3d300 ffff88061295bc08
[ 1027.002020]  ffffffff8197ef7a ffffea0000b3d300 ffffffff942dd148 dfffe90000000000
[ 1027.003359] Call Trace:
[ 1027.003831] dump_stack (lib/dump_stack.c:52)
[ 1027.004725] bad_page (mm/page_alloc.c:338)
[ 1027.005623] free_pages_prepare (mm/page_alloc.c:657 mm/page_alloc.c:763)
[ 1027.006761] free_hot_cold_page (mm/page_alloc.c:1438)
[ 1027.007772] ? __page_cache_release (mm/swap.c:66)
[ 1027.008815] put_page (mm/swap.c:270)
[ 1027.009665] page_cache_pipe_buf_release (fs/splice.c:93)
[ 1027.010888] __splice_from_pipe (fs/splice.c:784 fs/splice.c:886)
Quoted 9 lines
[ 1027.011917] ? might_fault (./arch/x86/include/asm/current.h:14 mm/memory.c:3734)
[ 1027.012856] ? pipe_lock (fs/pipe.c:69)
[ 1027.013728] ? write_pipe_buf (fs/splice.c:1534)
[ 1027.014756] vmsplice_to_user (fs/splice.c:1574)
[ 1027.015725] ? rcu_read_lock_held (kernel/rcu/update.c:169)
[ 1027.016757] ? __fget_light (include/linux/fdtable.h:80 fs/file.c:684)
[ 1027.017782] SyS_vmsplice (fs/splice.c:1656 fs/splice.c:1639)
[ 1027.018863] tracesys_phase2 (arch/x86/kernel/entry_64.S:529)

So what happened here? Userspace fed some mlocked memory into splice() and then, while splice() was running, userspace dropped its reference to the memory, leaving splice() with the last reference. Yet somehow, that page was still marked as being mlocked. I wouldn't expect the kernel to permit userspace to drop its reference to the memory without first clearing the mlocked state.

Quoted 2 lines

Is it possible to work out from trinity sources what the exact sequence was? Which syscalls are being used, for example?

Trinity can't really log anything because attempts to log syscalls slow everything down to a crawl to the point nothing reproduces.

I've just looked at that trace above, and got a bit more confused. I didn't think that you can mlock page cache. How would a user do that exactly?

Thanks,
Sasha

#4 lore raw
Quoted 17 lines · Sasha Levin
Quoted 15 lines · Andrew Morton
Quoted 7 lines
[ 1027.012856] ? pipe_lock (fs/pipe.c:69)
[ 1027.013728] ? write_pipe_buf (fs/splice.c:1534)
[ 1027.014756] vmsplice_to_user (fs/splice.c:1574)
[ 1027.015725] ? rcu_read_lock_held (kernel/rcu/update.c:169)
[ 1027.016757] ? __fget_light (include/linux/fdtable.h:80 fs/file.c:684)
[ 1027.017782] SyS_vmsplice (fs/splice.c:1656 fs/splice.c:1639)
[ 1027.018863] tracesys_phase2 (arch/x86/kernel/entry_64.S:529)

So what happened here? Userspace fed some mlocked memory into splice() and then, while splice() was running, userspace dropped its reference to the memory, leaving splice() with the last reference. Yet somehow, that page was still marked as being mlocked. I wouldn't expect the kernel to permit userspace to drop its reference to the memory without first clearing the mlocked state.

Quoted 5 lines
Quoted 2 lines

Is it possible to work out from trinity sources what the exact sequence was? Which syscalls are being used, for example?

Trinity can't really log anything because attempts to log syscalls slow everything down to a crawl to the point nothing reproduces.

If the machine is still alive after /proc/sys/kernel/tainted changes, trinity will dump a trinity-post-mortem.log somewhere[*] that should contain the last two syscalls each process did. (Even if logging is disabled).

It's not perfect however, and knowing that we passed a pointer to a syscall isn't always useful unless we also dump the data that pointer pointed at. It's a work in progress. I don't know if I'm going to get time to improve it any time soon though.

Dave

[*] wherever cwd happened to be when the main process exited.

maintainer
#5 lore raw
In reply to Sasha Levin
Quoted 46 lines · On Tue, 18 Nov 2014 22:44:02 -0500 Sasha Levin <[email protected]> wrote:
Quoted 45 lines · Andrew Morton
Quoted 7 lines · On Fri, 14 Nov 2014 09:39:40 -0500 Sasha Levin <[email protected]> wrote:
[ 1026.988043] BUG: Bad page state in process trinity-c374  pfn:23f70
[ 1026.989684] page:ffffea0000b3d300 count:0 mapcount:0 mapping:          (null) index:0x5b
[ 1026.991151] flags: 0x1fffff8028000c(referenced|uptodate|swapbacked|mlocked)
[ 1026.992410] page dumped because: PAGE_FLAGS_CHECK_AT_FREE flag(s) set
[ 1026.993479] bad because of flags:
[ 1026.994125] flags: 0x200000(mlocked)

Gee that new page dumping code is nice!

Quoted 16 lines
[ 1026.994816] Modules linked in:
[ 1026.995378] CPU: 7 PID: 7879 Comm: trinity-c374 Not tainted 3.18.0-rc4-next-20141113-sasha-00047-gd1763ce-dirty #1455
[ 1026.996123] FAULT_INJECTION: forcing a failure.
[ 1026.996123] name failslab, interval 100, probability 30, space 0, times -1
[ 1026.999050]  0000000000000000 0000000000000000 0000000000b3d300 ffff88061295bbd8
[ 1027.000676]  ffffffff92f71097 0000000000000000 ffffea0000b3d300 ffff88061295bc08
[ 1027.002020]  ffffffff8197ef7a ffffea0000b3d300 ffffffff942dd148 dfffe90000000000
[ 1027.003359] Call Trace:
[ 1027.003831] dump_stack (lib/dump_stack.c:52)
[ 1027.004725] bad_page (mm/page_alloc.c:338)
[ 1027.005623] free_pages_prepare (mm/page_alloc.c:657 mm/page_alloc.c:763)
[ 1027.006761] free_hot_cold_page (mm/page_alloc.c:1438)
[ 1027.007772] ? __page_cache_release (mm/swap.c:66)
[ 1027.008815] put_page (mm/swap.c:270)
[ 1027.009665] page_cache_pipe_buf_release (fs/splice.c:93)
[ 1027.010888] __splice_from_pipe (fs/splice.c:784 fs/splice.c:886)
Quoted 9 lines
[ 1027.011917] ? might_fault (./arch/x86/include/asm/current.h:14 mm/memory.c:3734)
[ 1027.012856] ? pipe_lock (fs/pipe.c:69)
[ 1027.013728] ? write_pipe_buf (fs/splice.c:1534)
[ 1027.014756] vmsplice_to_user (fs/splice.c:1574)
[ 1027.015725] ? rcu_read_lock_held (kernel/rcu/update.c:169)
[ 1027.016757] ? __fget_light (include/linux/fdtable.h:80 fs/file.c:684)
[ 1027.017782] SyS_vmsplice (fs/splice.c:1656 fs/splice.c:1639)
[ 1027.018863] tracesys_phase2 (arch/x86/kernel/entry_64.S:529)

So what happened here? Userspace fed some mlocked memory into splice() and then, while splice() was running, userspace dropped its reference to the memory, leaving splice() with the last reference. Yet somehow, that page was still marked as being mlocked. I wouldn't expect the kernel to permit userspace to drop its reference to the memory without first clearing the mlocked state.

Quoted 5 lines
Quoted 2 lines

Is it possible to work out from trinity sources what the exact sequence was? Which syscalls are being used, for example?

Trinity can't really log anything because attempts to log syscalls slow everything down to a crawl to the point nothing reproduces.

Ah. I was thinking that it could be worked out by looking at the trinity source around where it calls splice(). But I suspect that doesn't make sense if trinity just creates a zillion threads each of which sprays semi-random syscalls at the kernel(?).

Quoted 2 lines

I've just looked at that trace above, and got a bit more confused. I didn't think that you can mlock page cache. How would a user do that exactly?

mmap it then mlock it! The kernel will fault everything in for you then pin it down.

--
To unsubscribe, send a message with 'unsubscribe linux-mm' in the body to [email protected]. For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"[email protected]"> [email protected] </a>

author
#6 lore raw
Quoted 6 lines · Andrew Morton
Quoted 2 lines

Trinity can't really log anything because attempts to log syscalls slow everything

Quoted 1 line

down to a crawl to the point nothing reproduces.

Ah. I was thinking that it could be worked out by looking at the trinity source around where it calls splice(). But I suspect that doesn't make sense if trinity just creates a zillion threads each of which sprays semi-random syscalls at the kernel(?).

I think Dave would agree here that this is a rather accurate description of Trinity :)

Quoted 4 lines
Quoted 2 lines
Quoted 2 lines

I've just looked at that trace above, and got a bit more confused. I didn't think that you can mlock page cache. How would a user do that exactly?

mmap it then mlock it! The kernel will fault everything in for you then pin it down.

But that's a pipe buffer, I didn't think userspace can mmap pipes? I have some reading to do.

Thanks,
Sasha

#7 lore raw
In reply to Andrew Morton
Quoted 38 lines · Andrew Morton
Quoted 7 lines · On Fri, 14 Nov 2014 09:39:40 -0500 Sasha Levin <[email protected]> wrote:
[ 1026.988043] BUG: Bad page state in process trinity-c374  pfn:23f70
[ 1026.989684] page:ffffea0000b3d300 count:0 mapcount:0 mapping:          (null) index:0x5b
[ 1026.991151] flags: 0x1fffff8028000c(referenced|uptodate|swapbacked|mlocked)
[ 1026.992410] page dumped because: PAGE_FLAGS_CHECK_AT_FREE flag(s) set
[ 1026.993479] bad because of flags:
[ 1026.994125] flags: 0x200000(mlocked)

Gee that new page dumping code is nice!

Quoted 16 lines
[ 1026.994816] Modules linked in:
[ 1026.995378] CPU: 7 PID: 7879 Comm: trinity-c374 Not tainted 3.18.0-rc4-next-20141113-sasha-00047-gd1763ce-dirty #1455
[ 1026.996123] FAULT_INJECTION: forcing a failure.
[ 1026.996123] name failslab, interval 100, probability 30, space 0, times -1
[ 1026.999050]  0000000000000000 0000000000000000 0000000000b3d300 ffff88061295bbd8
[ 1027.000676]  ffffffff92f71097 0000000000000000 ffffea0000b3d300 ffff88061295bc08
[ 1027.002020]  ffffffff8197ef7a ffffea0000b3d300 ffffffff942dd148 dfffe90000000000
[ 1027.003359] Call Trace:
[ 1027.003831] dump_stack (lib/dump_stack.c:52)
[ 1027.004725] bad_page (mm/page_alloc.c:338)
[ 1027.005623] free_pages_prepare (mm/page_alloc.c:657 mm/page_alloc.c:763)
[ 1027.006761] free_hot_cold_page (mm/page_alloc.c:1438)
[ 1027.007772] ? __page_cache_release (mm/swap.c:66)
[ 1027.008815] put_page (mm/swap.c:270)
[ 1027.009665] page_cache_pipe_buf_release (fs/splice.c:93)
[ 1027.010888] __splice_from_pipe (fs/splice.c:784 fs/splice.c:886)
Quoted 9 lines
[ 1027.011917] ? might_fault (./arch/x86/include/asm/current.h:14 mm/memory.c:3734)
[ 1027.012856] ? pipe_lock (fs/pipe.c:69)
[ 1027.013728] ? write_pipe_buf (fs/splice.c:1534)
[ 1027.014756] vmsplice_to_user (fs/splice.c:1574)
[ 1027.015725] ? rcu_read_lock_held (kernel/rcu/update.c:169)
[ 1027.016757] ? __fget_light (include/linux/fdtable.h:80 fs/file.c:684)
[ 1027.017782] SyS_vmsplice (fs/splice.c:1656 fs/splice.c:1639)
[ 1027.018863] tracesys_phase2 (arch/x86/kernel/entry_64.S:529)
Quoted 6 lines

So what happened here? Userspace fed some mlocked memory into splice() and then, while splice() was running, userspace dropped its reference to the memory, leaving splice() with the last reference. Yet somehow, that page was still marked as being mlocked. I wouldn't expect the kernel to permit userspace to drop its reference to the memory without first clearing the mlocked state.

I did check a bit and something caught my eye. Both page_remove_rmap() and page_remove_file_rmap() contain this:

        if (unlikely(PageMlocked(page)))
                clear_page_mlock(page);

So could maybe something mlock the page between the check and clear?

I find lru_cache_add_active_or_unevictable somewhat suspicious. But checking if these two could race will take some time.

Quoted 9 lines

Is it possible to work out from trinity sources what the exact sequence was? Which syscalls are being used, for example?

--
To unsubscribe, send a message with 'unsubscribe linux-mm' in the body to [email protected]. For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"[email protected]"> [email protected] </a>

--
To unsubscribe, send a message with 'unsubscribe linux-mm' in the body to [email protected]. For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"[email protected]"> [email protected] </a>

author Acked-by Hugh Dickins Acked-by Mel Gorman
#8 lore raw
In reply to Andrew Morton
Quoted 32 lines · Andrew Morton
Quoted 25 lines
[ 1026.994816] Modules linked in:
Quoted 24 lines
[ 1026.995378] CPU: 7 PID: 7879 Comm: trinity-c374 Not tainted 3.18.0-rc4-next-20141113-sasha-00047-gd1763ce-dirty #1455
[ 1026.996123] FAULT_INJECTION: forcing a failure.
[ 1026.996123] name failslab, interval 100, probability 30, space 0, times -1
[ 1026.999050]  0000000000000000 0000000000000000 0000000000b3d300 ffff88061295bbd8
[ 1027.000676]  ffffffff92f71097 0000000000000000 ffffea0000b3d300 ffff88061295bc08
[ 1027.002020]  ffffffff8197ef7a ffffea0000b3d300 ffffffff942dd148 dfffe90000000000
[ 1027.003359] Call Trace:
[ 1027.003831] dump_stack (lib/dump_stack.c:52)
[ 1027.004725] bad_page (mm/page_alloc.c:338)
[ 1027.005623] free_pages_prepare (mm/page_alloc.c:657 mm/page_alloc.c:763)
[ 1027.006761] free_hot_cold_page (mm/page_alloc.c:1438)
[ 1027.007772] ? __page_cache_release (mm/swap.c:66)
[ 1027.008815] put_page (mm/swap.c:270)
[ 1027.009665] page_cache_pipe_buf_release (fs/splice.c:93)
[ 1027.010888] __splice_from_pipe (fs/splice.c:784 fs/splice.c:886)
[ 1027.011917] ? might_fault (./arch/x86/include/asm/current.h:14 mm/memory.c:3734)
[ 1027.012856] ? pipe_lock (fs/pipe.c:69)
[ 1027.013728] ? write_pipe_buf (fs/splice.c:1534)
[ 1027.014756] vmsplice_to_user (fs/splice.c:1574)
[ 1027.015725] ? rcu_read_lock_held (kernel/rcu/update.c:169)
[ 1027.016757] ? __fget_light (include/linux/fdtable.h:80 fs/file.c:684)
[ 1027.017782] SyS_vmsplice (fs/splice.c:1656 fs/splice.c:1639)
[ 1027.018863] tracesys_phase2 (arch/x86/kernel/entry_64.S:529)

So what happened here? Userspace fed some mlocked memory into splice() and then, while splice() was running, userspace dropped its reference to the memory, leaving splice() with the last reference. Yet somehow, that page was still marked as being mlocked. I wouldn't expect the kernel to permit userspace to drop its reference to the memory without first clearing the mlocked state.

Quoted 2 lines

Is it possible to work out from trinity sources what the exact sequence was? Which syscalls are being used, for example?

Phew, this took a long while but I've bisected it (with good confidence) down to:

commit a38246260912ba4a0f8b563704a965a7a97cf3c3

Author: Davidlohr Bueso <[email protected]>
Date:   Wed Dec 3 18:54:27 2014 +1100

mm/memory.c: share the i_mmap_rwsem

The unmap_mapping_range family of functions do the unmapping of user pages (ultimately via zap_page_range_single) without touching the actual interval tree, thus share the lock.

Signed-off-by Davidlohr Bueso <[email protected]>
Cc "Kirill A. Shutemov" <[email protected]>
Acked-by Hugh Dickins <[email protected]>
Cc Oleg Nesterov <[email protected]>
Cc Peter Zijlstra (Intel) <[email protected]>
Cc Rik van Riel <[email protected]>
Cc Srikar Dronamraju <[email protected]>
Acked-by Mel Gorman <[email protected]>
Signed-off-by Andrew Morton <[email protected]>

Thanks,
Sasha

author
#9 lore raw

(Apologies for spam, I've Cc'ed a few outdated emails in the previous mail)

Quoted 63 lines · Sasha Levin
Quoted 32 lines · Andrew Morton
Quoted 25 lines
[ 1026.994816] Modules linked in:
Quoted 24 lines
[ 1026.995378] CPU: 7 PID: 7879 Comm: trinity-c374 Not tainted 3.18.0-rc4-next-20141113-sasha-00047-gd1763ce-dirty #1455
[ 1026.996123] FAULT_INJECTION: forcing a failure.
[ 1026.996123] name failslab, interval 100, probability 30, space 0, times -1
[ 1026.999050]  0000000000000000 0000000000000000 0000000000b3d300 ffff88061295bbd8
[ 1027.000676]  ffffffff92f71097 0000000000000000 ffffea0000b3d300 ffff88061295bc08
[ 1027.002020]  ffffffff8197ef7a ffffea0000b3d300 ffffffff942dd148 dfffe90000000000
[ 1027.003359] Call Trace:
[ 1027.003831] dump_stack (lib/dump_stack.c:52)
[ 1027.004725] bad_page (mm/page_alloc.c:338)
[ 1027.005623] free_pages_prepare (mm/page_alloc.c:657 mm/page_alloc.c:763)
[ 1027.006761] free_hot_cold_page (mm/page_alloc.c:1438)
[ 1027.007772] ? __page_cache_release (mm/swap.c:66)
[ 1027.008815] put_page (mm/swap.c:270)
[ 1027.009665] page_cache_pipe_buf_release (fs/splice.c:93)
[ 1027.010888] __splice_from_pipe (fs/splice.c:784 fs/splice.c:886)
[ 1027.011917] ? might_fault (./arch/x86/include/asm/current.h:14 mm/memory.c:3734)
[ 1027.012856] ? pipe_lock (fs/pipe.c:69)
[ 1027.013728] ? write_pipe_buf (fs/splice.c:1534)
[ 1027.014756] vmsplice_to_user (fs/splice.c:1574)
[ 1027.015725] ? rcu_read_lock_held (kernel/rcu/update.c:169)
[ 1027.016757] ? __fget_light (include/linux/fdtable.h:80 fs/file.c:684)
[ 1027.017782] SyS_vmsplice (fs/splice.c:1656 fs/splice.c:1639)
[ 1027.018863] tracesys_phase2 (arch/x86/kernel/entry_64.S:529)

So what happened here? Userspace fed some mlocked memory into splice() and then, while splice() was running, userspace dropped its reference to the memory, leaving splice() with the last reference. Yet somehow, that page was still marked as being mlocked. I wouldn't expect the kernel to permit userspace to drop its reference to the memory without first clearing the mlocked state.

Quoted 2 lines

Is it possible to work out from trinity sources what the exact sequence was? Which syscalls are being used, for example?

Phew, this took a long while but I've bisected it (with good confidence) down to:

commit a38246260912ba4a0f8b563704a965a7a97cf3c3

Author: Davidlohr Bueso <[email protected]>
Date:   Wed Dec 3 18:54:27 2014 +1100

mm/memory.c: share the i_mmap_rwsem

The unmap_mapping_range family of functions do the unmapping of user pages (ultimately via zap_page_range_single) without touching the actual interval tree, thus share the lock.

Signed-off-by Davidlohr Bueso <[email protected]>
Cc "Kirill A. Shutemov" <[email protected]>
Acked-by Hugh Dickins <[email protected]>
Cc Oleg Nesterov <[email protected]>
Cc Peter Zijlstra (Intel) <[email protected]>
Cc Rik van Riel <[email protected]>
Cc Srikar Dronamraju <[email protected]>
Acked-by Mel Gorman <[email protected]>
Signed-off-by Andrew Morton <[email protected]>

Thanks,
Sasha