Bug 218230
| Summary: | xfstests xfs/538 hung | ||
|---|---|---|---|
| Product: | File System | Reporter: | Daniel Gomez (dagmcr) |
| Component: | XFS | Assignee: | FileSystem/XFS Default Virtual Assignee (filesystem_xfs) |
| Status: | NEW --- | ||
| Severity: | normal | CC: | sirius |
| Priority: | P3 | ||
| Hardware: | All | ||
| OS: | Linux | ||
| Kernel Version: | v6.6-rc5 | Subsystem: | |
| Regression: | No | Bisected commit-id: | |
|
Description
Daniel Gomez
2023-12-05 12:31:34 UTC
On Tue, Dec 05, 2023 at 12:31:34 PM +0000, bugzilla-daemon@kernel.org wrote: > https://bugzilla.kernel.org/show_bug.cgi?id=218230 > > Bug ID: 218230 > Summary: xfstests xfs/538 hung > Product: File System > Version: 2.5 > Hardware: All > OS: Linux > Status: NEW > Severity: normal > Priority: P3 > Component: XFS > Assignee: filesystem_xfs@kernel-bugs.kernel.org > Reporter: dagmcr@gmail.com > Regression: No > > While doing fstests baseline testing on v6.6-rc5 with kdevops [0] we found a > failure for xfs/538 test. > > [0] https://github.com/linux-kdevops > > This fails on the following test sections as defined by kdevops [1]: > > * xfs_crc_logdev_rtdev: failure rate ~1/17 > * xfs_crc_rtdev_extsize_64k: failure rate ~1/3 > > [0] https://github.com/linux-kdevops > [1] > > https://github.com/linux-kdevops/kdevops/blob/master/playbooks/roles/fstests/templates/xfs/xfs.config > > Below is just one full trace. > > Nov 02 20:23:13 line-xfs-crc-logdev-rtdev unknown: run fstests xfs/538 at > 2023-11-02 20:23:13 > Nov 02 20:23:14 line-xfs-crc-logdev-rtdev kernel: XFS (loop5): Mounting V5 > Filesystem 8e731ab8-42fb-48c5-8877-b4fb526e9609 > Nov 02 20:23:14 line-xfs-crc-logdev-rtdev kernel: XFS (loop5): Ending clean > mount > Nov 02 20:23:23 line-xfs-crc-logdev-rtdev kernel: XFS (loop5): Injecting > error > (false) at file fs/xfs/libxfs/xfs_bmap.c, line 4123, on filesystem "loop5" > Nov 02 20:23:23 line-xfs-crc-logdev-rtdev kernel: XFS (loop5): Injecting > error > (false) at file fs/xfs/libxfs/xfs_bmap.c, line 4082, on filesystem "loop5" > Nov 02 20:23:23 line-xfs-crc-logdev-rtdev kernel: XFS (loop5): Injecting > error > (false) at file fs/xfs/libxfs/xfs_bmap.c, line 4082, on filesystem "loop5" > Nov 02 20:23:23 line-xfs-crc-logdev-rtdev kernel: XFS (loop5): Injecting > error > (false) at file fs/xfs/libxfs/xfs_bmap.c, line 4082, on filesystem "loop5" > Nov 02 20:23:23 line-xfs-crc-logdev-rtdev kernel: XFS (loop5): Injecting > error > (false) at file fs/xfs/libxfs/xfs_bmap.c, line 4082, on filesystem "loop5" > Nov 02 20:23:23 line-xfs-crc-logdev-rtdev kernel: XFS (loop5): Injecting > error > (false) at file fs/xfs/libxfs/xfs_bmap.c, line 4082, on filesystem "loop5" > Nov 02 20:23:23 line-xfs-crc-logdev-rtdev kernel: XFS (loop5): Injecting > error > (false) at file fs/xfs/libxfs/xfs_bmap.c, line 4082, on filesystem "loop5" > Nov 02 20:23:23 line-xfs-crc-logdev-rtdev kernel: XFS (loop5): Injecting > error > (false) at file fs/xfs/libxfs/xfs_bmap.c, line 4082, on filesystem "loop5" > Nov 02 20:23:23 line-xfs-crc-logdev-rtdev kernel: XFS (loop5): Injecting > error > (false) at file fs/xfs/libxfs/xfs_bmap.c, line 4082, on filesystem "loop5" > Nov 02 20:23:23 line-xfs-crc-logdev-rtdev kernel: XFS (loop5): Injecting > error > (false) at file fs/xfs/libxfs/xfs_bmap.c, line 4082, on filesystem "loop5" > Nov 02 20:23:28 line-xfs-crc-logdev-rtdev kernel: xfs_errortag_test: 43825 > callbacks suppressed > Nov 02 20:23:28 line-xfs-crc-logdev-rtdev kernel: XFS (loop5): Injecting > error > (false) at file fs/xfs/libxfs/xfs_bmap.c, line 4082, on filesystem "loop5" > Nov 02 20:23:28 line-xfs-crc-logdev-rtdev kernel: XFS (loop5): Injecting > error > (false) at file fs/xfs/libxfs/xfs_bmap.c, line 4082, on filesystem "loop5" > Nov 02 20:23:28 line-xfs-crc-logdev-rtdev kernel: XFS (loop5): Injecting > error > (false) at file fs/xfs/libxfs/xfs_bmap.c, line 4082, on filesystem "loop5" > Nov 02 20:23:28 line-xfs-crc-logdev-rtdev kernel: XFS (loop5): Injecting > error > (false) at file fs/xfs/libxfs/xfs_bmap.c, line 4082, on filesystem "loop5" > Nov 02 20:23:28 line-xfs-crc-logdev-rtdev kernel: XFS (loop5): Injecting > error > (false) at file fs/xfs/libxfs/xfs_bmap.c, line 4082, on filesystem "loop5" > Nov 02 20:23:28 line-xfs-crc-logdev-rtdev kernel: XFS (loop5): Injecting > error > (false) at file fs/xfs/libxfs/xfs_bmap.c, line 4082, on filesystem "loop5" > Nov 02 20:23:28 line-xfs-crc-logdev-rtdev kernel: XFS (loop5): Injecting > error > (false) at file fs/xfs/libxfs/xfs_bmap.c, line 4082, on filesystem "loop5" > Nov 02 20:23:28 line-xfs-crc-logdev-rtdev kernel: XFS (loop5): Injecting > error > (false) at file fs/xfs/libxfs/xfs_bmap.c, line 4082, on filesystem "loop5" > Nov 02 20:23:28 line-xfs-crc-logdev-rtdev kernel: XFS (loop5): Injecting > error > (false) at file fs/xfs/libxfs/xfs_bmap.c, line 4082, on filesystem "loop5" > Nov 02 20:23:28 line-xfs-crc-logdev-rtdev kernel: XFS (loop5): Injecting > error > (false) at file fs/xfs/libxfs/xfs_bmap.c, line 4082, on filesystem "loop5" > Nov 02 20:23:33 line-xfs-crc-logdev-rtdev kernel: xfs_errortag_test: 37630 > callbacks suppressed > Nov 02 20:23:38 line-xfs-crc-logdev-rtdev kernel: XFS (loop5): Injecting > error > (false) at file fs/xfs/libxfs/xfs_bmap.c, line 4082, on filesystem "loop5" > Nov 02 20:23:38 line-xfs-crc-logdev-rtdev kernel: XFS (loop5): Injecting > error > (false) at file fs/xfs/libxfs/xfs_bmap.c, line 4082, on filesystem "loop5" > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: INFO: task kcompactd0:71 > blocked for more than 120 seconds. > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: Not tainted 6.6.0-rc5 > #2 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: "echo 0 > > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: task:kcompactd0 > state:D > stack:0 pid:71 ppid:2 flags:0x00004000 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: Call Trace: > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: <TASK> > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: __schedule+0x3ab/0xab0 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: schedule+0x5d/0xe0 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: io_schedule+0x42/0x70 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: > folio_wait_bit_common+0x12e/0x380 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? > __pfx_wake_page_function+0x10/0x10 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: > migrate_pages_batch+0x632/0xdb0 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? > __pfx_compaction_free+0x10/0x10 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? > __pfx_compaction_alloc+0x10/0x10 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? > __pfx_remove_migration_pte+0x10/0x10 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: migrate_pages+0xc22/0xda0 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? > __pfx_compaction_alloc+0x10/0x10 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? > __pfx_compaction_free+0x10/0x10 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: compact_zone+0x927/0xfe0 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? > _raw_spin_unlock+0x15/0x30 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? > finish_task_switch.isra.0+0x91/0x2a0 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? __switch_to+0x106/0x3a0 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: > proactive_compact_node+0x87/0xe0 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? finish_wait+0x41/0x90 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: kcompactd+0x30d/0x3f0 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? > __pfx_autoremove_wake_function+0x10/0x10 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? > __pfx_kcompactd+0x10/0x10 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: kthread+0xf3/0x120 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? __pfx_kthread+0x10/0x10 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ret_from_fork+0x30/0x50 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? __pfx_kthread+0x10/0x10 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: > ret_from_fork_asm+0x1b/0x30 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: </TASK> > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: INFO: task > kworker/5:0:2369803 blocked for more than 120 seconds. > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: Not tainted 6.6.0-rc5 > #2 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: "echo 0 > > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: task:kworker/5:0 > state:D > stack:0 pid:2369803 ppid:2 flags:0x00004000 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: Workqueue: > xfs-inodegc/loop5 > xfs_inodegc_worker [xfs] > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: Call Trace: > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: <TASK> > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: __schedule+0x3ab/0xab0 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? > finish_task_switch.isra.0+0x91/0x2a0 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: schedule+0x5d/0xe0 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: > schedule_timeout+0x143/0x150 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? > preempt_count_add+0x6a/0xa0 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: __down_common+0xf6/0x200 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: down+0x43/0x60 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: xfs_buf_lock+0x2d/0xe0 > [xfs] > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: > xfs_buf_find_lock+0x60/0x140 > [xfs] > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: > xfs_buf_get_map+0x1bd/0xaf0 > [xfs] > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? > __module_address+0x2f/0xb0 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? > __module_address+0x2f/0xb0 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? > preempt_count_add+0x47/0xa0 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: > xfs_buf_read_map+0x54/0x250 > [xfs] > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? xfs_read_agf+0x90/0x130 > [xfs] > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: > xfs_trans_read_buf_map+0x1c2/0x4d0 [xfs] > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? xfs_read_agf+0x90/0x130 > [xfs] > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: xfs_read_agf+0x90/0x130 > [xfs] > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: > xfs_alloc_read_agf+0x5e/0x390 [xfs] > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? > __xfs_trans_commit+0xc8/0x390 [xfs] > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: > xfs_alloc_fix_freelist+0x3cb/0x750 [xfs] > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? > unwind_next_frame+0x120/0x890 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? > arch_stack_walk+0x88/0xf0 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? > ret_from_fork_asm+0x1b/0x30 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? > __stack_depot_save+0x35/0x480 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: > xfs_free_extent_fix_freelist+0x61/0xa0 [xfs] > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: > __xfs_free_extent+0x8c/0x1f0 > [xfs] > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: > xfs_trans_free_extent+0x97/0x270 [xfs] > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: > xfs_extent_free_finish_item+0xf/0x40 [xfs] > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: > xfs_defer_finish_noroll+0x19f/0x760 [xfs] > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: xfs_defer_finish+0x11/0xa0 > [xfs] > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: > xfs_itruncate_extents_flags+0x14f/0x4c0 [xfs] > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: > xfs_inactive_truncate+0xbf/0x140 [xfs] > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: xfs_inactive+0x22d/0x290 > [xfs] > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: > xfs_inodegc_worker+0xb4/0x1a0 [xfs] > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: > process_one_work+0x174/0x340 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: worker_thread+0x277/0x390 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? > __pfx_worker_thread+0x10/0x10 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: kthread+0xf3/0x120 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? __pfx_kthread+0x10/0x10 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ret_from_fork+0x30/0x50 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? __pfx_kthread+0x10/0x10 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: > ret_from_fork_asm+0x1b/0x30 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: </TASK> > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: INFO: task > kworker/u17:7:3188941 blocked for more than 120 seconds. > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: Not tainted 6.6.0-rc5 > #2 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: "echo 0 > > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: task:kworker/u17:7 > state:D > stack:0 pid:3188941 ppid:2 flags:0x00004000 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: Workqueue: writeback > wb_workfn (flush-7:5) > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: Call Trace: > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: <TASK> > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: __schedule+0x3ab/0xab0 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: schedule+0x5d/0xe0 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: > schedule_timeout+0x143/0x150 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? > _raw_spin_unlock_irqrestore+0x23/0x40 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? > preempt_count_add+0x6a/0xa0 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? > _raw_spin_lock_irqsave+0x23/0x50 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: __down_common+0xf6/0x200 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: down+0x43/0x60 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: xfs_buf_lock+0x2d/0xe0 > [xfs] > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: > xfs_buf_find_lock+0x60/0x140 > [xfs] > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: > xfs_buf_get_map+0x1bd/0xaf0 > [xfs] > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? > _xfs_trans_bjoin+0x76/0x120 [xfs] > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: > xfs_buf_read_map+0x54/0x250 > [xfs] > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? xfs_read_agf+0x90/0x130 > [xfs] > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: > xfs_trans_read_buf_map+0x1c2/0x4d0 [xfs] > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? xfs_read_agf+0x90/0x130 > [xfs] > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: xfs_read_agf+0x90/0x130 > [xfs] > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: > xfs_alloc_read_agf+0x5e/0x390 [xfs] > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: > xfs_alloc_fix_freelist+0x3cb/0x750 [xfs] > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? wb_workfn+0x30f/0x4b0 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? > set_track_prepare+0x4a/0x70 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? > xlog_ticket_alloc+0x29/0xa0 [xfs] > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? > xfs_log_reserve+0x9c/0x220 > [xfs] > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? > xfs_trans_reserve+0x199/0x270 [xfs] > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? > __pv_queued_spin_lock_slowpath+0x16c/0x380 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: > xfs_alloc_vextent_prepare_ag+0x2d/0x120 [xfs] > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: > xfs_alloc_vextent_iterate_ags.constprop.0+0x99/0x230 [xfs] > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: > xfs_alloc_vextent_first_ag+0xf1/0x130 [xfs] > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: > xfs_bmap_exact_minlen_extent_alloc+0x138/0x1b0 [xfs] > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: > xfs_bmapi_allocate+0x282/0x450 [xfs] > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: > xfs_bmapi_convert_delalloc+0x2ee/0x4e0 [xfs] > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: xfs_map_blocks+0x1f2/0x590 > [xfs] > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: > iomap_do_writepage+0x28b/0x8d0 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: > write_cache_pages+0x159/0x3c0 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? > __pfx_iomap_do_writepage+0x10/0x10 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: iomap_writepages+0x1c/0x40 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: > xfs_vm_writepages+0x79/0xb0 > [xfs] > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: do_writepages+0xcb/0x1a0 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? touch_atime+0x1c/0x160 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? filemap_read+0x32f/0x340 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: > __writeback_single_inode+0x3d/0x350 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? _raw_spin_lock+0x13/0x40 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: > writeback_sb_inodes+0x1f5/0x4c0 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: > __writeback_inodes_wb+0x4c/0xe0 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: wb_writeback+0x26b/0x2e0 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: wb_workfn+0x30f/0x4b0 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? > _raw_spin_unlock+0x15/0x30 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? > finish_task_switch.isra.0+0x91/0x2a0 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? __switch_to+0x106/0x3a0 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: > process_one_work+0x174/0x340 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: worker_thread+0x277/0x390 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? > __pfx_worker_thread+0x10/0x10 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: kthread+0xf3/0x120 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? __pfx_kthread+0x10/0x10 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ret_from_fork+0x30/0x50 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: ? __pfx_kthread+0x10/0x10 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: > ret_from_fork_asm+0x1b/0x30 > Nov 02 20:27:11 line-xfs-crc-logdev-rtdev kernel: </TASK> I have root caused the bug and hope to post the patches soon. >
> I have root caused the bug and hope to post the patches soon.
Sorry, I had forgotten about this bug. Luis reminded me about this
recently. The patches I had written turned out to be incorrect. However, the
following provides the root cause analysis of the bug.
Executing xfs/538 on a Linux v6.6 kernel can lead to the following
deadlock,
|------------------+------------------+------------------|
| Task A | Task B | Task C |
|------------------+------------------+------------------|
| Lock AG 1's AGF | | |
| | Lock AG 2's AGI | |
| | Wait for lock on | |
| | AG 1's AGF | |
| | | Lock AG 3's AGF |
| | | Wait for lock on |
| | | AG 2's AGI |
| Wait for lock on | | |
| AG 3's AGF | | |
|------------------+------------------+------------------|
As illustrated above, Task B and C are violating the AG locking order
rule i.e. AGI/AGF must be locked in increasing AG order and that
within an AG, AGI must be locked before an AGF.
Task B's call trace:
context_switch (kernel/sched/core.c:5382:2)
__schedule (kernel/sched/core.c:6695:8)
schedule (kernel/sched/core.c:6771:3)
schedule_timeout (kernel/time/timer.c:2143:3)
___down_common (kernel/locking/semaphore.c:225:13)
__down_common (kernel/locking/semaphore.c:246:8)
down (kernel/locking/semaphore.c:63:3)
xfs_buf_lock (fs/xfs/xfs_buf.c:1126:2)
xfs_buf_find_lock (fs/xfs/xfs_buf.c:553:3)
xfs_buf_lookup (fs/xfs/xfs_buf.c:592:10)
xfs_buf_get_map (fs/xfs/xfs_buf.c:702:10)
xfs_buf_read_map (fs/xfs/xfs_buf.c:817:10)
xfs_trans_read_buf_map (fs/xfs/xfs_trans_buf.c:289:10)
xfs_trans_read_buf (./fs/xfs/xfs_trans.h:212:9)
xfs_read_agf (fs/xfs/libxfs/xfs_alloc.c:3153:10)
xfs_alloc_read_agf (fs/xfs/libxfs/xfs_alloc.c:3185:10)
xfs_alloc_fix_freelist (fs/xfs/libxfs/xfs_alloc.c:2658:11)
xfs_alloc_vextent_prepare_ag (fs/xfs/libxfs/xfs_alloc.c:3321:10)
xfs_alloc_vextent_iterate_ags (fs/xfs/libxfs/xfs_alloc.c:3506:11)
xfs_alloc_vextent_first_ag (fs/xfs/libxfs/xfs_alloc.c:3641:10)
xfs_bmap_exact_minlen_extent_alloc (fs/xfs/libxfs/xfs_bmap.c:3434:10)
xfs_bmap_alloc_userdata (fs/xfs/libxfs/xfs_bmap.c:4084:10)
xfs_bmapi_allocate (fs/xfs/libxfs/xfs_bmap.c:4129:11)
xfs_bmapi_write (fs/xfs/libxfs/xfs_bmap.c:4438:12)
xfs_symlink (fs/xfs/xfs_symlink.c:271:11)
xfs_vn_symlink (fs/xfs/xfs_iops.c:419:10)
vfs_symlink (fs/namei.c:4480:10)
vfs_symlink (fs/namei.c:4464:5)
do_symlinkat (fs/namei.c:4506:11)
__do_sys_symlink (fs/namei.c:4527:9)
__se_sys_symlink (fs/namei.c:4525:1)
__x64_sys_symlink (fs/namei.c:4525:1)
do_syscall_x64 (arch/x86/entry/common.c:50:14)
do_syscall_64 (arch/x86/entry/common.c:80:7)
entry_SYSCALL_64+0xaa/0x1a6 (arch/x86/entry/entry_64.S:120)
Task B above locked AG 2's AGI, allocated an ondisk inode, then tried
to allocate blocks (required for holding pathname representing the
symbolic link) from AG 1. This happened due to
xfs_bmap_exact_minlen_extent_alloc() iterating across AGs starting
from AG 0.
Task C's call trace:
context_switch (kernel/sched/core.c:5382:2)
__schedule (kernel/sched/core.c:6695:8)
schedule (kernel/sched/core.c:6771:3)
schedule_timeout (kernel/time/timer.c:2143:3)
___down_common (kernel/locking/semaphore.c:225:13)
__down_common (kernel/locking/semaphore.c:246:8)
down (kernel/locking/semaphore.c:63:3)
xfs_buf_lock (fs/xfs/xfs_buf.c:1126:2)
xfs_buf_find_lock (fs/xfs/xfs_buf.c:553:3)
xfs_buf_lookup (fs/xfs/xfs_buf.c:592:10)
xfs_buf_get_map (fs/xfs/xfs_buf.c:702:10)
xfs_buf_read_map (fs/xfs/xfs_buf.c:817:10)
xfs_trans_read_buf_map (fs/xfs/xfs_trans_buf.c:289:10)
xfs_trans_read_buf (./fs/xfs/xfs_trans.h:212:9)
xfs_read_agi (fs/xfs/libxfs/xfs_ialloc.c:2598:10)
xfs_ialloc_read_agi (fs/xfs/libxfs/xfs_ialloc.c:2626:10)
xfs_dialloc_try_ag (fs/xfs/libxfs/xfs_ialloc.c:1690:10)
xfs_dialloc (fs/xfs/libxfs/xfs_ialloc.c:1803:12)
xfs_create (fs/xfs/xfs_inode.c:1020:10)
xfs_generic_create (fs/xfs/xfs_iops.c:199:11)
vfs_mkdir (fs/namei.c:4120:10)
do_mkdirat (fs/namei.c:4143:11)
__do_sys_mkdir (fs/namei.c:4163:9)
__se_sys_mkdir (fs/namei.c:4161:1)
__x64_sys_mkdir (fs/namei.c:4161:1)
do_syscall_x64 (arch/x86/entry/common.c:50:14)
do_syscall_64 (arch/x86/entry/common.c:80:7)
entry_SYSCALL_64+0xaa/0x1a6 (arch/x86/entry/entry_64.S:120)
Task C above was trying to allocate an inode chunk to serve a mkdir()
syscall request. Task C locked AG 3's AGF and searched for the
required extent. However, the only suitable extent was found to be
straddling xfs_alloc_arg->max_agbno. Hence, it moved to the next AG
and ended up wrapping around the AG list.
|