include/net/9p/client.h | 15 +- net/9p/client.c | 508 +++++++++++++++++++++++++--------------- 2 files changed, 339 insertions(+), 184 deletions(-)
I've been working on async RPCs for a while and never had time to debug the last issues this had, but by limiting the async clunks to failures the impact is drastically smaller and I've not been able to reproduce any more bug so far. This will require some more testing and I'm tempted to say this is not worth rushing this into the merge window next week-ish; the new problem Jens reported with task_work isn't really new and I'd rather get this right than rush new bugs in given the sour experience I've had with this patch series... Hopefully it'll get in this time. With that in mind I plan to take the patches in to my -next branch after the merge window, so this has time to get reviewed first. I'd like to measure impact on performance as well, but really spent way more time on this than I already have, so that'll have to wait a bit. The only good thing here is that this shouldn't conflict with Eric's rework... A few problems I ran into today: - not doing async clunks for retries led to massive fid leaks as soon as I started doing async flush; I've described that in the clunk patch but basically all the servers we tested with always replied with the clunk before the flush, so the first clunk was never an error, so there wasn't a need to retry at all... Because if it had it'd fall with ERESTARTSYS immediately again, and it didn't. This isn't perfect, but hopefully should be good enough to avoid too many problems. - for flush itself, the waiting for all in-flight flushes before sending new rpc isn't great, but I don't have any better idea. I think in the general case we could get away with not waiting at all most of the time (check if there are any pending flush sent by the current tid?), but the current approach by making the thread not killable at all (!) is much more conservative, so I feel like we should try this much even if it costs a bit. Anyway, here goes nothing. Comments please! Dominique Martinet (5): 9p/net: move code in preparation of async rpc 9p/net: share pooled receive buffers size exception in p9_tag_alloc 9p/net: implement asynchronous rpc skeleton 9p/net: add async clunk for retries 9p/net: make flush asynchronous include/net/9p/client.h | 15 +- net/9p/client.c | 508 +++++++++++++++++++++++++--------------- 2 files changed, 339 insertions(+), 184 deletions(-) -- 2.39.1
Dominique Martinet wrote on Sat, Feb 11, 2023 at 04:50:18PM +0900: > A few problems I ran into today: > [...] Ah, one more thing I forgot: I'm still convinced that p9_virtio_zc_request is wrong in its current (before these patches), and adding this on top doesn't make it any better. We'll likely want to fix that too before merging this, giving another reason to dealy this for 6.4. p9_virtio_zc_request shouldn't unpin the pages if wait_event_killable is interrupted, and the flush async cb should call back in the transport to unpin at that point or something? I'm probably repeating myself here but I really don't have time in the day for everything, so that too will have to wait... (and there's probably more I forgot, but that'll do for now) -- Dominique
On Saturday, February 11, 2023 8:50:18 AM CET Dominique Martinet wrote: > I've been working on async RPCs for a while and never had time to debug > the last issues this had, but by limiting the async clunks to failures > the impact is drastically smaller and I've not been able to reproduce > any more bug so far. > > This will require some more testing and I'm tempted to say this is not > worth rushing this into the merge window next week-ish; the new problem > Jens reported with task_work isn't really new and I'd rather get this > right than rush new bugs in given the sour experience I've had with this > patch series... Hopefully it'll get in this time. > With that in mind I plan to take the patches in to my -next branch after > the merge window, so this has time to get reviewed first. > > I'd like to measure impact on performance as well, but really spent way > more time on this than I already have, so that'll have to wait a bit. I have not observed performance degradation, nor any (new) errors. So for this entire series: Tested-by: Christian Schoenebeck <linux_oss@crudebyte.com>
On Monday, February 13, 2023 7:26:54 PM CET Christian Schoenebeck wrote: > On Saturday, February 11, 2023 8:50:18 AM CET Dominique Martinet wrote: > > I've been working on async RPCs for a while and never had time to debug > > the last issues this had, but by limiting the async clunks to failures > > the impact is drastically smaller and I've not been able to reproduce > > any more bug so far. > > > > This will require some more testing and I'm tempted to say this is not > > worth rushing this into the merge window next week-ish; the new problem > > Jens reported with task_work isn't really new and I'd rather get this > > right than rush new bugs in given the sour experience I've had with this > > patch series... Hopefully it'll get in this time. > > With that in mind I plan to take the patches in to my -next branch after > > the merge window, so this has time to get reviewed first. > > > > I'd like to measure impact on performance as well, but really spent way > > more time on this than I already have, so that'll have to wait a bit. > > I have not observed performance degradation, nor any (new) errors. So for > this entire series: > > Tested-by: Christian Schoenebeck <linux_oss@crudebyte.com> Sorry, strike that. :-/ When unmounting the 9p file system it would fail (hang/timeout) to kill 9p processes: ... [ OK ] Reached target Unmount All Filesystems. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create System Users. [ OK ] Stopped Remount Root and Kernel File Systems. [ OK ] Reached target Shutdown. [ OK ] Reached target Final Step. [ OK ] Finished Power-Off. [ OK ] Reached target Power-Off. [ 323.019620] systemd-shutdown[1]: Syncing filesystems and block devices. [ 353.023371] systemd-shutdown[1]: Syncing filesystems and block devices - timed out, issuing SIGKILL to PID 10124. [ 353.028633] systemd-shutdown[1]: Sending SIGTERM to remaining processes... [ 363.033509] systemd-shutdown[1]: Waiting for process: (sd-sync), systemd-journal [ 443.037702] systemd-shutdown[1]: Sending SIGKILL to remaining processes... [ 443.045199] systemd-shutdown[1]: Sending SIGKILL to PID 237 (systemd-journal). [ 443.046891] systemd-shutdown[1]: Sending SIGKILL to PID 10124 ((sd-sync)). [ 453.048972] systemd-shutdown[1]: Waiting for process: (sd-sync), systemd-journal [ 484.756639] INFO: task systemd-journal:237 blocked for more than 120 seconds. [ 484.761954] Tainted: G E 6.2.0-rc6+ #62 [ 484.762940] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 484.764377] task:systemd-journal state:D stack:0 pid:237 ppid:1 flags:0x00004004 [ 484.765820] Call Trace: [ 484.766299] <TASK> [ 484.766667] __schedule (kernel/sched/core.c:5293 kernel/sched/core.c:6606) [ 484.767314] schedule (kernel/sched/core.c:6683 (discriminator 1)) [ 484.767901] io_schedule (kernel/sched/core.c:8843 kernel/sched/core.c:8869) [ 484.768486] folio_wait_bit_common (mm/filemap.c:1289) [ 484.769240] ? find_get_pages_range_tag (mm/filemap.c:2341) [ 484.770103] ? __pfx_wake_page_function (mm/filemap.c:1079) [ 484.770987] folio_wait_writeback (./arch/x86/include/asm/bitops.h:207 ./arch/x86/include/asm/bitops.h:239 ./include/asm-generic/bitops/instrumented-non-atomic.h:142 ./include/linux/page-flags.h:518 mm/page-writeback.c:3146) [ 484.771773] __filemap_fdatawait_range (./include/linux/page-flags.h:251 (discriminator 3) ./include/linux/page-flags.h:473 (discriminator 3) mm/filemap.c:522 (discriminator 3)) [ 484.772630] ? filemap_fdatawrite_wbc (mm/filemap.c:391) [ 484.773447] ? __filemap_fdatawrite_range (mm/filemap.c:422) [ 484.774350] filemap_write_and_wait_range (mm/filemap.c:685 mm/filemap.c:665) [ 484.775173] v9fs_vfs_setattr_dotl (./include/linux/pagemap.h:60 fs/9p/vfs_inode_dotl.c:586) 9p [ 484.775997] notify_change (fs/attr.c:486) [ 484.776657] ? __vfs_getxattr (fs/xattr.c:425) [ 484.777316] ? do_truncate (./include/linux/fs.h:761 fs/open.c:66) [ 484.777928] do_truncate (./include/linux/fs.h:761 fs/open.c:66) [ 484.778515] do_sys_ftruncate (fs/open.c:193) [ 484.779192] do_syscall_64 (arch/x86/entry/common.c:50 arch/x86/entry/common.c:80) [ 484.779790] entry_SYSCALL_64_after_hwframe (arch/x86/entry/entry_64.S:120) [ 484.780643] RIP: 0033:0x7fb8c0f6bb77 [ 484.781256] RSP: 002b:00007ffe74e6a5e8 EFLAGS: 00000206 ORIG_RAX: 000000000000004d [ 484.782526] RAX: ffffffffffffffda RBX: 00007ffe74e6a630 RCX: 00007fb8c0f6bb77 [ 484.783700] RDX: 0000561d6c28b0b0 RSI: 0000000001000000 RDI: 0000000000000014 [ 484.784905] RBP: 0000561d6c294bd0 R08: 0000000000000001 R09: 0000561d6c294c54 [ 484.786129] R10: 0000000000000010 R11: 0000000000000206 R12: 00007ffe74e6a628 [ 484.787323] R13: 0000561d6c284670 R14: 0000000000000703 R15: 0000000000000000 [ 484.788619] </TASK> [ 484.789152] INFO: task (sd-sync):10124 blocked for more than 120 seconds. [ 484.790622] Tainted: G E 6.2.0-rc6+ #62 [ 484.791660] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 484.793009] task:(sd-sync) state:D stack:0 pid:10124 ppid:1 flags:0x00000004 [ 484.794431] Call Trace: [ 484.794889] <TASK> [ 484.795312] __schedule (kernel/sched/core.c:5293 kernel/sched/core.c:6606) [ 484.795937] ? __pfx_sync_inodes_one_sb (fs/sync.c:75) [ 484.796751] schedule (kernel/sched/core.c:6683 (discriminator 1)) [ 484.797313] wb_wait_for_completion (fs/fs-writeback.c:192 fs/fs-writeback.c:189) [ 484.798042] ? __pfx_autoremove_wake_function (kernel/sched/wait.c:418) [ 484.798997] sync_inodes_sb (fs/fs-writeback.c:369 (discriminator 3) fs/fs-writeback.c:2726 (discriminator 3)) [ 484.799644] ? __pfx_sync_inodes_one_sb (fs/sync.c:75) [ 484.800486] iterate_supers (fs/super.c:725) [ 484.801184] ksys_sync (fs/sync.c:103) [ 484.801754] __do_sys_sync (fs/sync.c:115) [ 484.802372] do_syscall_64 (arch/x86/entry/common.c:50 arch/x86/entry/common.c:80) [ 484.802975] entry_SYSCALL_64_after_hwframe (arch/x86/entry/entry_64.S:120) [ 484.803868] RIP: 0033:0x7f41734a1447 [ 484.804496] RSP: 002b:00007ffc7f4de6a8 EFLAGS: 00000246 ORIG_RAX: 00000000000000a2 [ 484.805892] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f41734a1447 [ 484.807216] RDX: 00000000ffffffff RSI: 00000000ffffffff RDI: 0000000000000003 [ 484.808464] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000 [ 484.809701] R10: 0000000000000000 R11: 0000000000000246 R12: 00007ffc7f4dff2b [ 484.810857] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000 [ 484.812090] </TASK> [ 533.055563] systemd-shutdown[1]: Unmounting file systems. [ 533.059617] [10125]: Remounting '/' read-only in with options 'loose,access=client,msize=512000,trans=virtio'. [ 605.587527] INFO: task systemd-journal:237 blocked for more than 241 seconds. [ 605.592716] Tainted: G E 6.2.0-rc6+ #62 [ 605.593674] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 605.594956] task:systemd-journal state:D stack:0 pid:237 ppid:1 flags:0x00004004 [ 605.596415] Call Trace: [ 605.596884] <TASK> [ 605.597274] __schedule (kernel/sched/core.c:5293 kernel/sched/core.c:6606) [ 605.597875] schedule (kernel/sched/core.c:6683 (discriminator 1)) [ 605.598424] io_schedule (kernel/sched/core.c:8843 kernel/sched/core.c:8869) [ 605.599034] folio_wait_bit_common (mm/filemap.c:1289) [ 605.599830] ? find_get_pages_range_tag (mm/filemap.c:2341) [ 605.600750] ? __pfx_wake_page_function (mm/filemap.c:1079) [ 605.601607] folio_wait_writeback (./arch/x86/include/asm/bitops.h:207 ./arch/x86/include/asm/bitops.h:239 ./include/asm-generic/bitops/instrumented-non-atomic.h:142 ./include/linux/page-flags.h:518 mm/page-writeback.c:3146) [ 605.602314] __filemap_fdatawait_range (./include/linux/page-flags.h:251 (discriminator 3) ./include/linux/page-flags.h:473 (discriminator 3) mm/filemap.c:522 (discriminator 3)) [ 605.603217] ? filemap_fdatawrite_wbc (mm/filemap.c:391) [ 605.604060] ? __filemap_fdatawrite_range (mm/filemap.c:422) [ 605.604877] filemap_write_and_wait_range (mm/filemap.c:685 mm/filemap.c:665) [ 605.605737] v9fs_vfs_setattr_dotl (./include/linux/pagemap.h:60 fs/9p/vfs_inode_dotl.c:586) 9p [ 605.606560] notify_change (fs/attr.c:486) [ 605.607206] ? __vfs_getxattr (fs/xattr.c:425) [ 605.607871] ? do_truncate (./include/linux/fs.h:761 fs/open.c:66) [ 605.608510] do_truncate (./include/linux/fs.h:761 fs/open.c:66) [ 605.609118] do_sys_ftruncate (fs/open.c:193) [ 605.609867] do_syscall_64 (arch/x86/entry/common.c:50 arch/x86/entry/common.c:80) [ 605.610506] entry_SYSCALL_64_after_hwframe (arch/x86/entry/entry_64.S:120) [ 605.611401] RIP: 0033:0x7fb8c0f6bb77 [ 605.612038] RSP: 002b:00007ffe74e6a5e8 EFLAGS: 00000206 ORIG_RAX: 000000000000004d [ 605.613280] RAX: ffffffffffffffda RBX: 00007ffe74e6a630 RCX: 00007fb8c0f6bb77 [ 605.614449] RDX: 0000561d6c28b0b0 RSI: 0000000001000000 RDI: 0000000000000014 [ 605.615763] RBP: 0000561d6c294bd0 R08: 0000000000000001 R09: 0000561d6c294c54 [ 605.616952] R10: 0000000000000010 R11: 0000000000000206 R12: 00007ffe74e6a628 [ 605.618206] R13: 0000561d6c284670 R14: 0000000000000703 R15: 0000000000000000 [ 605.619547] </TASK> [ 605.619939] INFO: task (sd-sync):10124 blocked for more than 241 seconds. [ 605.621187] Tainted: G E 6.2.0-rc6+ #62 [ 605.622229] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 605.623518] task:(sd-sync) state:D stack:0 pid:10124 ppid:1 flags:0x00000004 [ 605.624907] Call Trace: [ 605.625340] <TASK> [ 605.625758] __schedule (kernel/sched/core.c:5293 kernel/sched/core.c:6606) [ 605.626397] ? __pfx_sync_inodes_one_sb (fs/sync.c:75) [ 605.627263] schedule (kernel/sched/core.c:6683 (discriminator 1)) [ 605.627802] wb_wait_for_completion (fs/fs-writeback.c:192 fs/fs-writeback.c:189) [ 605.628530] ? __pfx_autoremove_wake_function (kernel/sched/wait.c:418) [ 605.629380] sync_inodes_sb (fs/fs-writeback.c:369 (discriminator 3) fs/fs-writeback.c:2726 (discriminator 3)) [ 605.630014] ? __pfx_sync_inodes_one_sb (fs/sync.c:75) [ 605.630789] iterate_supers (fs/super.c:725) [ 605.631428] ksys_sync (fs/sync.c:103) [ 605.631999] __do_sys_sync (fs/sync.c:115) [ 605.632669] do_syscall_64 (arch/x86/entry/common.c:50 arch/x86/entry/common.c:80) [ 605.633293] entry_SYSCALL_64_after_hwframe (arch/x86/entry/entry_64.S:120) [ 605.634188] RIP: 0033:0x7f41734a1447 [ 605.634870] RSP: 002b:00007ffc7f4de6a8 EFLAGS: 00000246 ORIG_RAX: 00000000000000a2 [ 605.636181] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f41734a1447 [ 605.637444] RDX: 00000000ffffffff RSI: 00000000ffffffff RDI: 0000000000000003 [ 605.638750] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000 [ 605.640032] R10: 0000000000000000 R11: 0000000000000246 R12: 00007ffc7f4dff2b [ 605.641313] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000 [ 605.642465] </TASK> [ 623.059026] systemd-shutdown[1]: Remounting '/' timed out, issuing SIGKILL to PID 10125. [ 623.064583] systemd-shutdown[1]: Not all file systems unmounted, 1 left. [ 623.066046] systemd-shutdown[1]: Deactivating swaps. [ 623.067274] systemd-shutdown[1]: All swaps deactivated. [ 623.068436] systemd-shutdown[1]: Detaching loop devices. [ 623.070645] systemd-shutdown[1]: All loop devices detached. [ 623.071918] systemd-shutdown[1]: Stopping MD devices. [ 623.073602] systemd-shutdown[1]: All MD devices stopped. [ 623.074785] systemd-shutdown[1]: Detaching DM devices. [ 623.076416] systemd-shutdown[1]: All DM devices detached. [ 623.077981] systemd-shutdown[1]: Unmounting file systems. [ 623.080197] [10126]: Remounting '/' read-only in with options 'loose,access=client,msize=512000,trans=virtio'. [ 713.079672] systemd-shutdown[1]: Remounting '/' timed out, issuing SIGKILL to PID 10126. [ 713.085323] systemd-shutdown[1]: Not all file systems unmounted, 1 left. [ 713.086770] systemd-shutdown[1]: Cannot finalize remaining file systems, continuing. [ 713.092483] systemd-shutdown[1]: Failed to finalize file systems, ignoring. [ 713.094816] systemd-shutdown[1]: Syncing filesystems and block devices. [ 726.418246] INFO: task systemd-journal:237 blocked for more than 362 seconds. [ 726.423366] Tainted: G E 6.2.0-rc6+ #62 [ 726.424320] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 726.425672] task:systemd-journal state:D stack:0 pid:237 ppid:1 flags:0x00004004 [ 726.427132] Call Trace: [ 726.427583] <TASK> [ 726.427968] __schedule (kernel/sched/core.c:5293 kernel/sched/core.c:6606) [ 726.428586] schedule (kernel/sched/core.c:6683 (discriminator 1)) [ 726.429145] io_schedule (kernel/sched/core.c:8843 kernel/sched/core.c:8869) [ 726.429753] folio_wait_bit_common (mm/filemap.c:1289) [ 726.430562] ? find_get_pages_range_tag (mm/filemap.c:2341) [ 726.431427] ? __pfx_wake_page_function (mm/filemap.c:1079) [ 726.432254] folio_wait_writeback (./arch/x86/include/asm/bitops.h:207 ./arch/x86/include/asm/bitops.h:239 ./include/asm-generic/bitops/instrumented-non-atomic.h:142 ./include/linux/page-flags.h:518 mm/page-writeback.c:3146) [ 726.432987] __filemap_fdatawait_range (./include/linux/page-flags.h:251 (discriminator 3) ./include/linux/page-flags.h:473 (discriminator 3) mm/filemap.c:522 (discriminator 3)) [ 726.433815] ? filemap_fdatawrite_wbc (mm/filemap.c:391) [ 726.434625] ? __filemap_fdatawrite_range (mm/filemap.c:422) [ 726.435470] filemap_write_and_wait_range (mm/filemap.c:685 mm/filemap.c:665) [ 726.436313] v9fs_vfs_setattr_dotl (./include/linux/pagemap.h:60 fs/9p/vfs_inode_dotl.c:586) 9p [ 726.437168] notify_change (fs/attr.c:486) [ 726.437791] ? __vfs_getxattr (fs/xattr.c:425) [ 726.438483] ? do_truncate (./include/linux/fs.h:761 fs/open.c:66) [ 726.439120] do_truncate (./include/linux/fs.h:761 fs/open.c:66) [ 726.439723] do_sys_ftruncate (fs/open.c:193) [ 726.440407] do_syscall_64 (arch/x86/entry/common.c:50 arch/x86/entry/common.c:80) [ 726.441051] entry_SYSCALL_64_after_hwframe (arch/x86/entry/entry_64.S:120) [ 726.441882] RIP: 0033:0x7fb8c0f6bb77 [ 726.442517] RSP: 002b:00007ffe74e6a5e8 EFLAGS: 00000206 ORIG_RAX: 000000000000004d [ 726.443826] RAX: ffffffffffffffda RBX: 00007ffe74e6a630 RCX: 00007fb8c0f6bb77 [ 726.445068] RDX: 0000561d6c28b0b0 RSI: 0000000001000000 RDI: 0000000000000014 [ 726.446318] RBP: 0000561d6c294bd0 R08: 0000000000000001 R09: 0000561d6c294c54 [ 726.447541] R10: 0000000000000010 R11: 0000000000000206 R12: 00007ffe74e6a628 [ 726.448776] R13: 0000561d6c284670 R14: 0000000000000703 R15: 0000000000000000 [ 726.449968] </TASK> [ 726.450373] INFO: task (sd-sync):10124 blocked for more than 362 seconds. [ 726.451534] Tainted: G E 6.2.0-rc6+ #62 [ 726.452537] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 726.453896] task:(sd-sync) state:D stack:0 pid:10124 ppid:1 flags:0x00000004 [ 726.455307] Call Trace: [ 726.455747] <TASK> [ 726.456132] __schedule (kernel/sched/core.c:5293 kernel/sched/core.c:6606) [ 726.456756] ? __pfx_sync_inodes_one_sb (fs/sync.c:75) [ 726.457584] schedule (kernel/sched/core.c:6683 (discriminator 1)) [ 726.458157] wb_wait_for_completion (fs/fs-writeback.c:192 fs/fs-writeback.c:189) [ 726.458932] ? __pfx_autoremove_wake_function (kernel/sched/wait.c:418) [ 726.459847] sync_inodes_sb (fs/fs-writeback.c:369 (discriminator 3) fs/fs-writeback.c:2726 (discriminator 3)) [ 726.460513] ? __pfx_sync_inodes_one_sb (fs/sync.c:75) [ 726.461340] iterate_supers (fs/super.c:725) [ 726.462001] ksys_sync (fs/sync.c:103) [ 726.462567] __do_sys_sync (fs/sync.c:115) [ 726.463188] do_syscall_64 (arch/x86/entry/common.c:50 arch/x86/entry/common.c:80) [ 726.463825] entry_SYSCALL_64_after_hwframe (arch/x86/entry/entry_64.S:120) [ 726.464683] RIP: 0033:0x7f41734a1447 [ 726.465256] RSP: 002b:00007ffc7f4de6a8 EFLAGS: 00000246 ORIG_RAX: 00000000000000a2 [ 726.466581] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f41734a1447 [ 726.467795] RDX: 00000000ffffffff RSI: 00000000ffffffff RDI: 0000000000000003 [ 726.469025] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000 [ 726.470273] R10: 0000000000000000 R11: 0000000000000246 R12: 00007ffc7f4dff2b [ 726.471510] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000 [ 726.472746] </TASK> [ 726.473147] INFO: task (sd-remount):10125 blocked for more than 120 seconds. [ 726.474313] Tainted: G E 6.2.0-rc6+ #62 [ 726.475318] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 726.476664] task:(sd-remount) state:D stack:0 pid:10125 ppid:1 flags:0x00000004 [ 726.478116] Call Trace: [ 726.478523] <TASK> [ 726.478884] __schedule (kernel/sched/core.c:5293 kernel/sched/core.c:6606) [ 726.479479] ? memcg_slab_post_alloc_hook (./include/linux/percpu-refcount.h:174 ./include/linux/percpu-refcount.h:332 ./include/linux/percpu-refcount.h:351 ./include/linux/memcontrol.h:794 mm/slab.h:553) [ 726.480340] schedule (kernel/sched/core.c:6683 (discriminator 1)) [ 726.480851] rwsem_down_write_slowpath (kernel/locking/rwsem.c:1192) [ 726.481668] ? alloc_fs_context (fs/fs_context.c:291) [ 726.482390] path_mount (fs/namespace.c:2806 fs/namespace.c:3467) [ 726.483011] __x64_sys_mount (fs/namespace.c:3489 fs/namespace.c:3697 fs/namespace.c:3674 fs/namespace.c:3674) [ 726.483698] do_syscall_64 (arch/x86/entry/common.c:50 arch/x86/entry/common.c:80) [ 726.484326] entry_SYSCALL_64_after_hwframe (arch/x86/entry/entry_64.S:120) [ 726.485191] RIP: 0033:0x7f41734ab62a [ 726.485764] RSP: 002b:00007ffc7f4de7c8 EFLAGS: 00000246 ORIG_RAX: 00000000000000a5 [ 726.487081] RAX: ffffffffffffffda RBX: 000055c5c844aa10 RCX: 00007f41734ab62a [ 726.488247] RDX: 0000000000000000 RSI: 000055c5c844aa50 RDI: 0000000000000000 [ 726.489475] RBP: 0000000000000000 R08: 000055c5c844a9d0 R09: 000055c5c844a9d0 [ 726.490718] R10: 00000000003000a1 R11: 0000000000000246 R12: 00007ffc7f4de900 [ 726.491900] R13: 0000000000000000 R14: 00007ffc7f4de848 R15: 0000000000000000 [ 726.493003] </TASK> [ 743.099066] systemd-shutdown[1]: Syncing filesystems and block devices - timed out, issuing SIGKILL to PID 10129. [ 743.104366] systemd-shutdown[1]: Powering off. [ 743.213283] ACPI: PM: Preparing to enter system sleep state S5 [ 743.214425] reboot: Power down
Christian Schoenebeck wrote on Mon, Feb 13, 2023 at 07:45:34PM +0100: > On Monday, February 13, 2023 7:26:54 PM CET Christian Schoenebeck wrote: > > On Saturday, February 11, 2023 8:50:18 AM CET Dominique Martinet wrote: > > > I've been working on async RPCs for a while and never had time to debug > > > the last issues this had, but by limiting the async clunks to failures > > > the impact is drastically smaller and I've not been able to reproduce > > > any more bug so far. > > > > > > This will require some more testing and I'm tempted to say this is not > > > worth rushing this into the merge window next week-ish; the new problem > > > Jens reported with task_work isn't really new and I'd rather get this > > > right than rush new bugs in given the sour experience I've had with this > > > patch series... Hopefully it'll get in this time. > > > With that in mind I plan to take the patches in to my -next branch after > > > the merge window, so this has time to get reviewed first. > > > > > > I'd like to measure impact on performance as well, but really spent way > > > more time on this than I already have, so that'll have to wait a bit. > > > > I have not observed performance degradation, nor any (new) errors. So for > > this entire series: > > > > Tested-by: Christian Schoenebeck <linux_oss@crudebyte.com> > > Sorry, strike that. :-/ Ugh! thanks for the test, I'm not making much sense of the trace (folio wait bit means some background write isn't happening when flushing before the setattr?) but I'll try to reproduce and have a look today/tomorrow -- Dominique
On Monday, February 13, 2023 11:37:50 PM CET Dominique Martinet wrote:
> Christian Schoenebeck wrote on Mon, Feb 13, 2023 at 07:45:34PM +0100:
> > On Monday, February 13, 2023 7:26:54 PM CET Christian Schoenebeck wrote:
> > > On Saturday, February 11, 2023 8:50:18 AM CET Dominique Martinet wrote:
> > > > I've been working on async RPCs for a while and never had time to debug
> > > > the last issues this had, but by limiting the async clunks to failures
> > > > the impact is drastically smaller and I've not been able to reproduce
> > > > any more bug so far.
> > > >
> > > > This will require some more testing and I'm tempted to say this is not
> > > > worth rushing this into the merge window next week-ish; the new problem
> > > > Jens reported with task_work isn't really new and I'd rather get this
> > > > right than rush new bugs in given the sour experience I've had with this
> > > > patch series... Hopefully it'll get in this time.
> > > > With that in mind I plan to take the patches in to my -next branch after
> > > > the merge window, so this has time to get reviewed first.
> > > >
> > > > I'd like to measure impact on performance as well, but really spent way
> > > > more time on this than I already have, so that'll have to wait a bit.
> > >
> > > I have not observed performance degradation, nor any (new) errors. So for
> > > this entire series:
> > >
> > > Tested-by: Christian Schoenebeck <linux_oss@crudebyte.com>
> >
> > Sorry, strike that. :-/
>
> Ugh! thanks for the test, I'm not making much sense of the trace (folio
> wait bit means some background write isn't happening when flushing
> before the setattr?) but I'll try to reproduce and have a look
> today/tomorrow
Yes, apparently it tries to write dirty pages of the mapped file and keeps
hanging there [fs/9p/vfs_inode_dotl.c:586]:
int v9fs_vfs_setattr_dotl(struct user_namespace *mnt_userns,
struct dentry *dentry, struct iattr *iattr)
{
...
/* Write all dirty data */
if (S_ISREG(inode->i_mode))
filemap_write_and_wait(inode->i_mapping); <-- Hang
retval = p9_client_setattr(fid, &p9attr);
...
}
Christian Schoenebeck wrote on Tue, Feb 14, 2023 at 10:34:36AM +0100: > > Ugh! thanks for the test, I'm not making much sense of the trace (folio > > wait bit means some background write isn't happening when flushing > > before the setattr?) but I'll try to reproduce and have a look > > today/tomorrow > > Yes, apparently it tries to write dirty pages of the mapped file and keeps > hanging there [fs/9p/vfs_inode_dotl.c:586]: Yeah, it'd help to get the trace of the thread actually trying to do the IO, if it still exists. I had some hangs in the check that there are no flush in flight at some point, and I thought I fixed that, but I can't really see anywhere else that'd start hanging with this... it'll be clearer if I can reproduce. Anyway, I found another bug, just running ./configure on a random project (picked coreutils tarball) fails with interrupted system call ?! checking for gawk... gawk checking whether make sets $(MAKE)... yes checking whether make supports nested variables... yes checking whether make supports nested variables... (cached) yes checking for gcc... gcc ./configure: line 6385: can't create conftest.c: Interrupted system call checking whether the C compiler works... no sed: can't read conftest.c: No such file or directory configure: error: in `/mnt/coreutils-9.1': configure: error: C compiler cannot create executables See `config.log' for more details This obviously doesn't happen if I run with `sh -x configure`, but through execsnoop I caught it's just calling 'gcc conftest.c' and there's nothing special in here... But it doesn't happen without these patches, so I get something to dig at first. With a bit of luck it's the same root cause... -- Dominique
It's been a while but I didn't forget... Dominique Martinet wrote on Tue, Feb 14, 2023 at 08:16:38PM +0900: > > Yes, apparently it tries to write dirty pages of the mapped file and keeps > > hanging there [fs/9p/vfs_inode_dotl.c:586]: > > Yeah, it'd help to get the trace of the thread actually trying to do the > IO, if it still exists. > I had some hangs in the check that there are no flush in flight at some > point, and I thought I fixed that, but I can't really see anywhere else > that'd start hanging with this... it'll be clearer if I can reproduce. I couldn't reproduce this one, but manually inspecting p9_client_wait_flush again I noticed the wait_event_interruptible was waiting on req->flushed_req->wq but looking at req->status in the condition; that was an error. Also, we have a ref on req->flushed_req but not on req, so req->flushed_req wasn't safe. I've changed the code to add a variable directly on req->flushed_req and use it consistently, I'm not sure that's the problem you ran into but it might help. It's been a while but do you remember if that hang was consistently happening on shutdown, or was it a one time thing? Either way, I'd appreciate if you could try my 9p-test branch again: https://github.com/martinetd/linux/commits/9p-test With that said, I expect that p9_client_wait_req will cause hangs on broken servers. If connection drops hopefully the reqs will just be marked as error and free the thread, but I can see syzbot complaining about yet another thread stuck.. Well it's interruptible at least, and bails out on ERESTARTSYS. > Anyway, I found another bug, just running ./configure on a random project > (picked coreutils tarball) fails with interrupted system call ?! That other bug was weird, I could reproduce it reliably until I rebooted the host because of an unrelated nfs bug on the host, and after reboot I couldn't reproduce anymore. I'll chalk it down to buggy host/weird happenstance, but something to watch for if random EINTR happen again :/ -- Dominique
On Sunday, March 19, 2023 12:53:46 PM CET Dominique Martinet wrote: > It's been a while but I didn't forget... > > Dominique Martinet wrote on Tue, Feb 14, 2023 at 08:16:38PM +0900: > > > Yes, apparently it tries to write dirty pages of the mapped file and keeps > > > hanging there [fs/9p/vfs_inode_dotl.c:586]: > > > > Yeah, it'd help to get the trace of the thread actually trying to do the > > IO, if it still exists. > > I had some hangs in the check that there are no flush in flight at some > > point, and I thought I fixed that, but I can't really see anywhere else > > that'd start hanging with this... it'll be clearer if I can reproduce. > > I couldn't reproduce this one, but manually inspecting > p9_client_wait_flush again I noticed the wait_event_interruptible was > waiting on req->flushed_req->wq but looking at req->status in the > condition; that was an error. > Also, we have a ref on req->flushed_req but not on req, so > req->flushed_req wasn't safe. > > I've changed the code to add a variable directly on req->flushed_req and > use it consistently, I'm not sure that's the problem you ran into but it > might help. > It's been a while but do you remember if that hang was consistently > happening on shutdown, or was it a one time thing? > > Either way, I'd appreciate if you could try my 9p-test branch again: > https://github.com/martinetd/linux/commits/9p-test > > > With that said, I expect that p9_client_wait_req will cause hangs on > broken servers. > If connection drops hopefully the reqs will just be marked as error and > free the thread, but I can see syzbot complaining about yet another > thread stuck.. Well it's interruptible at least, and bails out on > ERESTARTSYS. I gave your current test branch some spins today. And yes, the problem did not happen reliably each time, but consistently enough for me to reproduce it. With your latest test branch it appears to have mitigated the problem. Once in a while on shutdown I see it blocking for few minutes, but recovering: [** ] (2 of 3) A stop job is running for …ave Random Seed (2min 36s / 10min) [ 484.986388] INFO: task systemd-user-ru:8782 blocked for more than 120 seconds. [ 484.990150] Tainted: G E 6.3.0-rc2+ #63 [ 484.992553] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 484.993657] task:systemd-user-ru state:D stack:0 pid:8782 ppid:1 flags:0x00000004 [ 484.994863] Call Trace: [ 484.995398] <TASK> [ 484.995866] __schedule (kernel/sched/core.c:5304 kernel/sched/core.c:6622) [ 484.996614] schedule (kernel/sched/core.c:6699 (discriminator 1)) [ 484.997283] d_alloc_parallel (./include/linux/spinlock.h:350 fs/dcache.c:2626 fs/dcache.c:2707) [ 484.998150] ? __pfx_default_wake_function (kernel/sched/core.c:6944) [ 484.999213] __lookup_slow (fs/namei.c:1671) [ 485.000006] walk_component (./include/linux/fs.h:773 fs/namei.c:1704 fs/namei.c:1994) [ 485.000805] path_lookupat (fs/namei.c:2451 fs/namei.c:2475) [ 485.001594] filename_lookup (fs/namei.c:2504) [ 485.002452] ? __check_object_size (mm/usercopy.c:196 mm/usercopy.c:251 mm/usercopy.c:213) [ 485.003523] ? strncpy_from_user (./include/asm-generic/access_ok.h:40 ./arch/x86/include/asm/uaccess.h:551 lib/strncpy_from_user.c:138) [ 485.004537] user_path_at_empty (fs/namei.c:2879) [ 485.005508] do_faccessat (fs/open.c:484) [ 485.006410] do_syscall_64 (arch/x86/entry/common.c:50 arch/x86/entry/common.c:80) [ 485.007281] entry_SYSCALL_64_after_hwframe (arch/x86/entry/entry_64.S:120) [ 485.008495] RIP: 0033:0x7f7b4527d8f7 [ 485.009380] RSP: 002b:00007ffc9ee73c08 EFLAGS: 00000246 ORIG_RAX: 0000000000000015 [ 485.011118] RAX: ffffffffffffffda RBX: 00007f7b44ee2608 RCX: 00007f7b4527d8f7 [ 485.012831] RDX: 000000000000001c RSI: 0000000000000000 RDI: 00007f7b44eda86b [ 485.014560] RBP: 0000000000000003 R08: 0000000000000000 R09: 00007f7b45360be0 [ 485.016246] R10: 00005571ade756c0 R11: 0000000000000246 R12: 00007ffc9ee73cf8 [ 485.017937] R13: 00007ffc9ee73d18 R14: 00007f7b44ee2610 R15: 0000000000000000 [ 485.019669] </TASK> However that happens now before unmount rule is reached on shutdown? Previously it was hanging after the shutdown rule was reached. Does this make sense? > > Anyway, I found another bug, just running ./configure on a random project > > (picked coreutils tarball) fails with interrupted system call ?! > > That other bug was weird, I could reproduce it reliably until I rebooted > the host because of an unrelated nfs bug on the host, and after reboot I > couldn't reproduce anymore. > I'll chalk it down to buggy host/weird happenstance, but something to > watch for if random EINTR happen again :/
On Thursday, March 23, 2023 4:58:51 PM CET Christian Schoenebeck wrote: > On Sunday, March 19, 2023 12:53:46 PM CET Dominique Martinet wrote: > > It's been a while but I didn't forget... > > > > Dominique Martinet wrote on Tue, Feb 14, 2023 at 08:16:38PM +0900: > > > > Yes, apparently it tries to write dirty pages of the mapped file and keeps > > > > hanging there [fs/9p/vfs_inode_dotl.c:586]: > > > > > > Yeah, it'd help to get the trace of the thread actually trying to do the > > > IO, if it still exists. > > > I had some hangs in the check that there are no flush in flight at some > > > point, and I thought I fixed that, but I can't really see anywhere else > > > that'd start hanging with this... it'll be clearer if I can reproduce. > > > > I couldn't reproduce this one, but manually inspecting > > p9_client_wait_flush again I noticed the wait_event_interruptible was > > waiting on req->flushed_req->wq but looking at req->status in the > > condition; that was an error. > > Also, we have a ref on req->flushed_req but not on req, so > > req->flushed_req wasn't safe. > > > > I've changed the code to add a variable directly on req->flushed_req and > > use it consistently, I'm not sure that's the problem you ran into but it > > might help. > > It's been a while but do you remember if that hang was consistently > > happening on shutdown, or was it a one time thing? > > > > Either way, I'd appreciate if you could try my 9p-test branch again: > > https://github.com/martinetd/linux/commits/9p-test > > > > > > With that said, I expect that p9_client_wait_req will cause hangs on > > broken servers. > > If connection drops hopefully the reqs will just be marked as error and > > free the thread, but I can see syzbot complaining about yet another > > thread stuck.. Well it's interruptible at least, and bails out on > > ERESTARTSYS. > > I gave your current test branch some spins today. > > And yes, the problem did not happen reliably each time, but consistently > enough for me to reproduce it. > > With your latest test branch it appears to have mitigated the problem. Once in > a while on shutdown I see it blocking for few minutes, but recovering: > > [** ] (2 of 3) A stop job is running for …ave Random Seed (2min 36s / 10min) > [ 484.986388] INFO: task systemd-user-ru:8782 blocked for more than 120 seconds. > [ 484.990150] Tainted: G E 6.3.0-rc2+ #63 > [ 484.992553] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > [ 484.993657] task:systemd-user-ru state:D stack:0 pid:8782 ppid:1 flags:0x00000004 > [ 484.994863] Call Trace: > [ 484.995398] <TASK> > [ 484.995866] __schedule (kernel/sched/core.c:5304 kernel/sched/core.c:6622) > [ 484.996614] schedule (kernel/sched/core.c:6699 (discriminator 1)) > [ 484.997283] d_alloc_parallel (./include/linux/spinlock.h:350 fs/dcache.c:2626 fs/dcache.c:2707) > [ 484.998150] ? __pfx_default_wake_function (kernel/sched/core.c:6944) > [ 484.999213] __lookup_slow (fs/namei.c:1671) > [ 485.000006] walk_component (./include/linux/fs.h:773 fs/namei.c:1704 fs/namei.c:1994) > [ 485.000805] path_lookupat (fs/namei.c:2451 fs/namei.c:2475) > [ 485.001594] filename_lookup (fs/namei.c:2504) > [ 485.002452] ? __check_object_size (mm/usercopy.c:196 mm/usercopy.c:251 mm/usercopy.c:213) > [ 485.003523] ? strncpy_from_user (./include/asm-generic/access_ok.h:40 ./arch/x86/include/asm/uaccess.h:551 lib/strncpy_from_user.c:138) > [ 485.004537] user_path_at_empty (fs/namei.c:2879) > [ 485.005508] do_faccessat (fs/open.c:484) > [ 485.006410] do_syscall_64 (arch/x86/entry/common.c:50 arch/x86/entry/common.c:80) > [ 485.007281] entry_SYSCALL_64_after_hwframe (arch/x86/entry/entry_64.S:120) > [ 485.008495] RIP: 0033:0x7f7b4527d8f7 > [ 485.009380] RSP: 002b:00007ffc9ee73c08 EFLAGS: 00000246 ORIG_RAX: 0000000000000015 > [ 485.011118] RAX: ffffffffffffffda RBX: 00007f7b44ee2608 RCX: 00007f7b4527d8f7 > [ 485.012831] RDX: 000000000000001c RSI: 0000000000000000 RDI: 00007f7b44eda86b > [ 485.014560] RBP: 0000000000000003 R08: 0000000000000000 R09: 00007f7b45360be0 > [ 485.016246] R10: 00005571ade756c0 R11: 0000000000000246 R12: 00007ffc9ee73cf8 > [ 485.017937] R13: 00007ffc9ee73d18 R14: 00007f7b44ee2610 R15: 0000000000000000 > [ 485.019669] </TASK> > > However that happens now before unmount rule is reached on shutdown? > Previously it was hanging after the shutdown rule was reached. Does this make > sense? Correction: I still get the previous issue on unmount with your latest version as well. :/ Call trace looks slightly different, but it seems to be the same issue: [ OK ] Reached target Unmount All Filesystems. [* ] A stop job is running for Load/Save Random Seed (3min 27s / 10min) [ 243.031668] INFO: task systemd-journal:199 blocked for more than 120 seconds. [ 243.036460] Tainted: G E 6.3.0-rc2+ #63 [ 243.037666] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 243.039004] task:systemd-journal state:D stack:0 pid:199 ppid:1 flags:0x00004004 [ 243.040434] Call Trace: [ 243.040878] <TASK> [ 243.041265] __schedule (kernel/sched/core.c:5304 kernel/sched/core.c:6622) [ 243.041887] ? __pagevec_release (./include/linux/pagevec.h:38 mm/swap.c:1063) [ 243.042594] schedule (kernel/sched/core.c:6699 (discriminator 1)) [ 243.043150] io_schedule (kernel/sched/core.c:8859 kernel/sched/core.c:8885) [ 243.043751] folio_wait_bit_common (mm/filemap.c:1293) [ 243.044519] ? __pfx_wake_page_function (mm/filemap.c:1083) [ 243.045321] folio_wait_writeback (./arch/x86/include/asm/bitops.h:207 ./arch/x86/include/asm/bitops.h:239 ./include/asm-generic/bitops/instrumented-non-atomic.h:142 ./include/linux/page-flags.h:518 mm/page-writeback.c:3125) [ 243.046043] __filemap_fdatawait_range (./arch/x86/include/asm/bitops.h:75 (discriminator 3) ./include/asm-generic/bitops/instrumented-atomic.h:42 (discriminator 3) ./include/linux/page-flags.h:473 (discriminator 3) mm/filemap.c:526 (discriminator 3)) [ 243.046828] ? filemap_fdatawrite_wbc (mm/filemap.c:393) [ 243.047622] ? __filemap_fdatawrite_range (mm/filemap.c:424) [ 243.048531] filemap_write_and_wait_range (mm/filemap.c:689 mm/filemap.c:669) [ 243.049358] v9fs_vfs_setattr_dotl (./include/linux/pagemap.h:60 fs/9p/vfs_inode_dotl.c:587) 9p [ 243.050229] notify_change (fs/attr.c:486) [ 243.050924] ? __vfs_getxattr (fs/xattr.c:426) [ 243.051571] ? do_truncate (./include/linux/fs.h:763 fs/open.c:67) [ 243.052224] do_truncate (./include/linux/fs.h:763 fs/open.c:67) [ 243.052816] do_sys_ftruncate (fs/open.c:194) [ 243.053548] do_syscall_64 (arch/x86/entry/common.c:50 arch/x86/entry/common.c:80) [ 243.054187] entry_SYSCALL_64_after_hwframe (arch/x86/entry/entry_64.S:120) [ 243.055057] RIP: 0033:0x7f6db123ab77 [ 243.055706] RSP: 002b:00007ffc4dda0ca8 EFLAGS: 00000206 ORIG_RAX: 000000000000004d [ 243.056978] RAX: ffffffffffffffda RBX: 00007ffc4dda0cf0 RCX: 00007f6db123ab77 [ 243.058198] RDX: 000055715f9b2a00 RSI: 0000000001000000 RDI: 0000000000000018 [ 243.059478] RBP: 000055715f9b2bf0 R08: 0000000000000001 R09: 000055715f9b2c74 [ 243.060716] R10: 0000000000000000 R11: 0000000000000206 R12: 00007ffc4dda0ce8 I just realized I don't have to do anything fancy to reproduce this. I just have to boot and shutdown guest few times to trigger it.
© 2016 - 2025 Red Hat, Inc.