Details
-
Bug
-
Resolution: Not a Bug
-
Minor
-
None
-
Lustre 2.12.8
-
None
-
Ubuntu 20.04 and 22.04
Kernel 5.13 and 5.15
-
3
-
9223372036854775807
Description
A Lustre client running kdb+ application, accessing a unique Lustre filesystem, crashed when running a read mostly workload with the following details:
LustreError: 2189:0:(osc_object.c:415:osc_req_attr_set()) page@000000006ff324cc[4 000000006e5cd158 3 1 0000000000000000] LustreError: 2189:0:(osc_object.c:415:osc_req_attr_set()) vvp-page@000000005896944a(0:0) vm@00000000f05ece12 17ffffc0002001 4:0 ffff9052622abe00 262400 lru LustreError: 2189:0:(osc_object.c:415:osc_req_attr_set()) lov-page@0000000040ca418a, comp index: 10000, gen: 3 LustreError: 2189:0:(osc_object.c:415:osc_req_attr_set()) osc-page@0000000090b283c9 52480: 1< 0x845fed 1 0 + + > 2< 214958080 0 4096 0x7 0x9 | 0000000000000000 00000000c2efe449 0000000047d0bab5 > 3< 1 18 0 > 4< 0 0 8 1879157331 - | - - - + > 5< - - - + | 0 - | 0 - -> LustreError: 2189:0:(osc_object.c:415:osc_req_attr_set()) end page@000000006ff324cc LustreError: 2189:0:(osc_object.c:415:osc_req_attr_set()) uncovered page! LustreError: 2189:0:(ldlm_resource.c:1764:ldlm_resource_dump()) --- Resource: [0x1cedf:0x0:0x0].0x0 (00000000de919111) refcount = 2 LustreError: 2189:0:(ldlm_resource.c:1768:ldlm_resource_dump()) Granted locks (in reverse order): LustreError: 2189:0:(ldlm_resource.c:1771:ldlm_resource_dump()) ### ### ns: kneitbmv-OST000b-osc-ffff905252cb9000 lock: 0000000040a3d2a7/0x6a51fb9756d1bd42 lrc: 3/1,0 mode: PR/PR res: [0x1cedf:0x0:0x0].0x0 rrc: 3 type: EXT [0->18446744073709551615] (req 214958080->216006655) flags: 0x800020000000000 nid: local remote: 0x9ca45c0e329718ca expref: -99 pid: 2639 timeout: 0 lvb_type: 1
The debugging logs tell that the page is not protected by an LDLM lock, but the LDLM resource output show thats a PR EXTENT LOCK is available for the whole object range.
crash> bt 2189 PID: 2189 TASK: ffff9052491a5e80 CPU: 9 COMMAND: "ptlrpcd_03_00" #0 [ffffbb01027b3900] machine_kexec at ffffffffae68c2a0 #1 [ffffbb01027b3960] __crash_kexec at ffffffffae798f72 #2 [ffffbb01027b3a30] panic at ffffffffaf303b8e #3 [ffffbb01027b3ac8] osc_req_attr_set at ffffffffc0ca5251 [osc] #4 [ffffbb01027b3b08] cl_req_attr_set at ffffffffc0a85670 [obdclass] #5 [ffffbb01027b3b38] osc_build_rpc at ffffffffc0c9f666 [osc] #6 [ffffbb01027b3bf8] osc_extent_finish at ffffffffc0cbf606 [osc] #7 [ffffbb01027b3cf0] brw_queue_work at ffffffffc0c94264 [osc] #8 [ffffbb01027b3d10] work_interpreter at ffffffffc0dbc9a3 [ptlrpc] #9 [ffffbb01027b3d30] ptlrpc_check_set at ffffffffc0dc4bd2 [ptlrpc] #10 [ffffbb01027b3dc8] ptlrpcd_check at ffffffffc0df0d79 [ptlrpc] #11 [ffffbb01027b3e20] ptlrpcd at ffffffffc0df1137 [ptlrpc] #12 [ffffbb01027b3f10] kthread at ffffffffae6e99b7 #13 [ffffbb01027b3f50] ret_from_fork at ffffffffae604cbf
LDLM lock says the lock was taken by PID 2639
crash> bt 2639 PID: 2639 TASK: ffff9052562bde80 CPU: 7 COMMAND: "q" #0 [ffffbb012304b808] __schedule at ffffffffaf3b500d #1 [ffffbb012304b890] schedule at ffffffffaf3b53be #2 [ffffbb012304b8b0] io_schedule at ffffffffaf3b54a6 #3 [ffffbb012304b8c8] wait_on_page_bit_common at ffffffffae8af4fc #4 [ffffbb012304b968] filemap_update_page at ffffffffae8b2382 #5 [ffffbb012304b9a8] filemap_get_pages at ffffffffae8b2612 #6 [ffffbb012304ba48] filemap_read at ffffffffae8b284c #7 [ffffbb012304bb50] generic_file_read_iter at ffffffffae8b2c55 #8 [ffffbb012304bb98] vvp_io_read_start at ffffffffc10cdd04 [lustre] #9 [ffffbb012304bc10] cl_io_start at ffffffffc0a85528 [obdclass] #10 [ffffbb012304bc48] cl_io_loop at ffffffffc0a88a4f [obdclass] #11 [ffffbb012304bc80] ll_file_io_generic at ffffffffc10882e1 [lustre] #12 [ffffbb012304bd80] ll_file_read_iter at ffffffffc1089101 [lustre] #13 [ffffbb012304bdc8] new_sync_read at ffffffffae989aba #14 [ffffbb012304be58] vfs_read at ffffffffae98a453 #15 [ffffbb012304be98] ksys_read at ffffffffae98cf27 #16 [ffffbb012304bed8] __x64_sys_read at ffffffffae98cfc9 #17 [ffffbb012304bee8] do_syscall_64 at ffffffffaf3a7fa9 RIP: 00007f87f70e09cc RSP: 00007ffd6bef11f0 RFLAGS: 00000246 RAX: ffffffffffffffda RBX: 0000000000000006 RCX: 00007f87f70e09cc RDX: 00000000001fffff RSI: 00007f794dc00009 RDI: 0000000000000006 RBP: 00007f794dc00009 R8: 0000000000000000 R9: 00007ffd6bef12c0 R10: 0000000000000000 R11: 0000000000000246 R12: 00007ffd6bef1348 R13: 0000000000000001 R14: 00000000001fffff R15: 00000000001fffff ORIG_RAX: 0000000000000000 CS: 0033 SS: 002b PID: 2637 TASK: ffff9052562bbf00 CPU: 9 COMMAND: "q" #0 [ffffbb01018bf6f0] __schedule at ffffffffaf3b500d #1 [ffffbb01018bf778] schedule at ffffffffaf3b53be #2 [ffffbb01018bf798] cl_sync_io_wait at ffffffffc0a87cd7 [obdclass] #3 [ffffbb01018bf808] ll_io_read_page at ffffffffc10a9727 [lustre] #4 [ffffbb01018bf8e8] ll_readpage at ffffffffc10ab1dc [lustre] #5 [ffffbb01018bf938] filemap_read_page at ffffffffae8afa58 #6 [ffffbb01018bf960] filemap_update_page at ffffffffae8b231c #7 [ffffbb01018bf9a0] filemap_get_pages at ffffffffae8b2612 #8 [ffffbb01018bfa40] filemap_read at ffffffffae8b284c #9 [ffffbb01018bfb48] generic_file_read_iter at ffffffffae8b2c55 #10 [ffffbb01018bfb90] vvp_io_read_start at ffffffffc10cdd04 [lustre] #11 [ffffbb01018bfc08] cl_io_start at ffffffffc0a85528 [obdclass] #12 [ffffbb01018bfc40] cl_io_loop at ffffffffc0a88a4f [obdclass] #13 [ffffbb01018bfc78] ll_file_io_generic at ffffffffc10882e1 [lustre] #14 [ffffbb01018bfd78] ll_file_read_iter at ffffffffc1089101 [lustre] #15 [ffffbb01018bfdc0] new_sync_read at ffffffffae989aba #16 [ffffbb01018bfe50] vfs_read at ffffffffae98a453 #17 [ffffbb01018bfe90] ksys_read at ffffffffae98cf27 #18 [ffffbb01018bfed0] __x64_sys_read at ffffffffae98cfc9 #19 [ffffbb01018bfee0] do_syscall_64 at ffffffffaf3a7fa9 #20 [ffffbb01018bff50] entry_SYSCALL_64_after_hwframe at ffffffffaf400099 RIP: 00007fe7e07e59cc RSP: 00007ffc950e6010 RFLAGS: 00000246 RAX: ffffffffffffffda RBX: 0000000000000006 RCX: 00007fe7e07e59cc RDX: 00000000001fffff RSI: 00007fdbfce00009 RDI: 0000000000000006 RBP: 00007fdbfce00009 R8: 0000000000000000 R9: 00007ffc950e60e0 R10: 0000000000000000 R11: 0000000000000246 R12: 00007ffc950e6168 R13: 0000000000000001 R14: 00000000001fffff R15: 00000000001fffff ORIG_RAX: 0000000000000000 CS: 0033 SS: 002b crash> ps -l 2189 2637 2639 [668349169196534] [UN] PID: 2639 TASK: ffff9052562bde80 CPU: 7 COMMAND: "q" [668349163196875] [RU] PID: 2189 TASK: ffff9052491a5e80 CPU: 9 COMMAND: "ptlrpcd_03_00" [668349163179612] [IN] PID: 2637 TASK: ffff9052562bbf00 CPU: 9 COMMAND: "q"
- Multiple occurrences of this bug demonstrates that the crash is always happening while the client is trying to read the second stripe of the file, either with standard striping (-c 5) or with PFL striping (-E 1G -c 1 -E EOF -c 5).
- Also, retrying few millisecs later seems to return the right lock.
![[Whamcloud Community Wiki] Page](/images/icons/generic_link_16.png "[Whamcloud Community Wiki] Page"){kind=icon}
There is a kernel bug at 5.12+ version where filemap_get_pages() adds additional page to IO.
So the main cl_io_loop() locks n pages, and IO has n+1. And as result uncovered page during rpc build.
We got it with small read IO 328 bytes first page, and failed with second page. First page should be cached.
#0 [ffffc9000e51f7e0] __schedule at ffffffff817d601a #1 [ffffc9000e51f870] schedule at ffffffff817d66da #2 [ffffc9000e51f880] cl_sync_io_wait at ffffffffa32c98ec [obdclass] #3 [ffffc9000e51f8e0] ll_io_read_page at ffffffffa3790a97 [lustre] #4 [ffffc9000e51f998] ll_readpage at ffffffffa379192a [lustre] #5 [ffffc9000e51fa00] filemap_read_page at ffffffff8120a78c #6 [ffffc9000e51fa88] filemap_get_pages at ffffffff8120daf5 #7 [ffffc9000e51fb18] filemap_read at ffffffff8120ddb2 #8 [ffffc9000e51fc10] vvp_io_read_start at ffffffffa37ba656 [lustre] #9 [ffffc9000e51fca0] cl_io_start at ffffffffa32c780c [obdclass] #10 [ffffc9000e51fcc8] cl_io_loop at ffffffffa32ca9aa [obdclass] #11 [ffffc9000e51fd00] ll_file_io_generic at ffffffffa3765dc1 [lustre] #12 [ffffc9000e51fdf0] ll_file_read_iter at ffffffffa3767179 [lustre] #13 [ffffc9000e51fe48] new_sync_read at ffffffff812cc42c ci_rw = { crw_pos = 1576, crw_count = 328, crw_nonblock = 0 }, pagevec ffffc9000e51fb58 struct pagevec { nr = 2 '\002', percpu_pvec_drained = false, pages = {0xffffea00d7974bc0, 0xffffea00402ed000, 0x63efe890, 0x20f1e572, 0x5ec9cc249c85a600, 0xffff88b10260d260, 0x1fe049d0, 0xffffc9000e51fbc8, 0xffffffff812f0a0d <atime_needs_update+141>, 0xffff88b10260d260, 0x1fe049d0, 0xffff88a0f2b6c0a0, 0xffff88968a342b48, 0xffffc9000e51fc08, 0xffffffff812f0aa4 <touch_atime+52>} }Here is the kernel fix
ommit 5956592ce337330cdff0399a6f8b6a5aea397a8e Author: Qian Yingjin <qian@ddn.com> Date: Wed Feb 8 10:24:00 2023 +0800 mm/filemap: fix page end in filemap_get_read_batch I was running traces of the read code against an RAID storage system to understand why read requests were being misaligned against the underlying RAID strips. I found that the page end offset calculation in filemap_get_read_batch() was off by one. When a read is submitted with end offset 1048575, then it calculates the end page for read of 256 when it should be 255. "last_index" is the index of the page beyond the end of the read and it should be skipped when get a batch of pages for read in @filemap_get_read_batch(). The below simple patch fixes the problem. This code was introduced in kernel 5.12. Link: https://lkml.kernel.org/r/20230208022400.28962-1-coolqyj@163.com Fixes: cbd59c48ae2b ("mm/filemap: use head pages in generic_file_buffered_read") Signed-off-by: Qian Yingjin <qian@ddn.com> Reviewed-by: Matthew Wilcox (Oracle) <willy@infradead.org> Cc: <stable@vger.kernel.org> Signed-off-by: Andrew Morton <akpm@linux-foundation.org> diff --git a/mm/filemap.c b/mm/filemap.c index c4d4ace9cc70..0e20a8d6dd93 100644 --- a/mm/filemap.c +++ b/mm/filemap.c @@ -2588,18 +2588,19 @@ static int filemap_get_pages(struct kiocb *iocb, struct iov_iter *iter, struct folio *folio; int err = 0; + /* "last_index" is the index of the page beyond the end of the read */ last_index = DIV_ROUND_UP(iocb->ki_pos + iter->count, PAGE_SIZE); retry: if (fatal_signal_pending(current)) return -EINTR; - filemap_get_read_batch(mapping, index, last_index, fbatch); + filemap_get_read_batch(mapping, index, last_index - 1, fbatch); if (!folio_batch_count(fbatch)) { if (iocb->ki_flags & IOCB_NOIO) return -EAGAIN; page_cache_sync_readahead(mapping, ra, filp, index, last_index - index); - filemap_get_read_batch(mapping, index, last_index, fbatch); + filemap_get_read_batch(mapping, index, last_index - 1, fbatch); } if (!folio_batch_count(fbatch)) { if (iocb->ki_flags & (IOCB_NOWAIT | IOCB_WAITQ))