* odebuf and lockdep splat with bcachefs
@ 2023-10-31 3:07 Guenter Roeck
2023-10-31 14:11 ` Brian Foster
0 siblings, 1 reply; 3+ messages in thread
From: Guenter Roeck @ 2023-10-31 3:07 UTC (permalink / raw)
To: linux-bcachefs; +Cc: Kent Overstreet, Brian Foster
Hi,
when trying the new bcachefs in the mainline kernel, I see the
attached ODEBUG and lockdep splats.
This is simply mounting an empty bcachefs file system and
copying some files into it.
Guenter
---
...
[ 11.653586] bcachefs (nvme0n1p2): fix_reflink_p... done
[ 11.656803] ODEBUG: object ffff80008164bb80 is on stack ffff800081648000, but NOT annotated.
[ 11.657192]
[ 11.657202] ======================================================
[ 11.657209] WARNING: possible circular locking dependency detected
[ 11.657271] 6.6.0-03474-gcd063c8b9e1e #1 Tainted: G N
[ 11.657281] ------------------------------------------------------
[ 11.657288] bch-copygc/nvme/790 is trying to acquire lock:
[ 11.657323] ffffac9250236a70 (console_owner){....}-{0:0}, at: console_flush_all+0x1b0/0x510
[ 11.657507]
[ 11.657507] but task is already holding lock:
[ 11.657514] ffffac9251375218 (&obj_hash[i].lock){-.-.}-{2:2}, at: __debug_object_init+0xac/0x20c
[ 11.657543]
[ 11.657543] which lock already depends on the new lock.
[ 11.657543]
[ 11.657548]
[ 11.657548] the existing dependency chain (in reverse order) is:
[ 11.657568]
[ 11.657568] -> #4 (&obj_hash[i].lock){-.-.}-{2:2}:
[ 11.657628] _raw_spin_lock_irqsave+0x60/0x88
[ 11.657675] debug_object_activate+0x108/0x290
[ 11.657684] insert_work+0x38/0xb0
[ 11.657694] __queue_work+0x1c4/0x674
[ 11.657701] queue_work_on+0xa8/0xe4
[ 11.657708] start_poll_synchronize_rcu_expedited+0x108/0x10c
[ 11.657717] rcu_init+0xb08/0xd3c
[ 11.657728] start_kernel+0x250/0x684
[ 11.657735] __primary_switched+0xbc/0xc4
[ 11.657779]
[ 11.657779] -> #3 (&pool->lock){-.-.}-{2:2}:
[ 11.657802] _raw_spin_lock+0x48/0x60
[ 11.657821] __queue_work+0x240/0x674
[ 11.657828] queue_work_on+0xa8/0xe4
[ 11.657835] rpm_suspend+0x4f0/0x644
[ 11.657844] rpm_idle+0x11c/0x2d4
[ 11.657851] __pm_runtime_idle+0x40/0xac
[ 11.657858] __device_attach+0xdc/0x1b0
[ 11.657866] device_initial_probe+0x14/0x20
[ 11.657874] bus_probe_device+0xb0/0xb4
[ 11.657881] device_add+0x5c8/0x784
[ 11.657890] serial_base_port_add+0x118/0x198
[ 11.657899] serial_core_register_port+0x74/0x5d4
[ 11.657907] serial_ctrl_register_port+0x10/0x1c
[ 11.657915] uart_add_one_port+0x10/0x1c
[ 11.657923] pl011_register_port+0x70/0x12c
[ 11.657930] pl011_probe+0x1ac/0x1e0
[ 11.657937] amba_probe+0x110/0x1c4
[ 11.657947] really_probe+0x148/0x2ac
[ 11.657954] __driver_probe_device+0x78/0x12c
[ 11.657962] driver_probe_device+0x3c/0x10c
[ 11.657969] __device_attach_driver+0xb8/0xf8
[ 11.657977] bus_for_each_drv+0x80/0xdc
[ 11.657984] __device_attach+0xa8/0x1b0
[ 11.657991] device_initial_probe+0x14/0x20
[ 11.657998] bus_probe_device+0xb0/0xb4
[ 11.658005] device_add+0x5c8/0x784
[ 11.658015] amba_device_add+0x40/0xac
[ 11.658024] of_platform_bus_create+0x2b4/0x378
[ 11.658033] of_platform_populate+0x50/0xfc
[ 11.658039] of_platform_default_populate_init+0xd0/0xf0
[ 11.658049] do_one_initcall+0x74/0x2f0
[ 11.658056] kernel_init_freeable+0x2a0/0x4f8
[ 11.658064] kernel_init+0x24/0x1e0
[ 11.658072] ret_from_fork+0x10/0x20
[ 11.658087]
[ 11.658087] -> #2 (&dev->power.lock){-...}-{2:2}:
[ 11.658103] _raw_spin_lock_irqsave+0x60/0x88
[ 11.658112] __pm_runtime_resume+0x48/0xb8
[ 11.658119] __uart_start+0x4c/0xf4
[ 11.658127] uart_write+0xec/0x2bc
[ 11.658134] n_tty_write+0x1cc/0x49c
[ 11.658143] file_tty_write.constprop.0+0x128/0x2b4
[ 11.658150] redirected_tty_write+0xbc/0xdc
[ 11.658157] vfs_write+0x220/0x2c4
[ 11.658166] ksys_write+0x68/0xf4
[ 11.658173] __arm64_sys_write+0x1c/0x28
[ 11.658181] invoke_syscall+0x48/0x114
[ 11.658191] el0_svc_common.constprop.0+0x40/0xe8
[ 11.658200] do_el0_svc+0x20/0x2c
[ 11.658208] el0_svc+0x58/0x120
[ 11.658216] el0t_64_sync_handler+0x13c/0x158
[ 11.658224] el0t_64_sync+0x190/0x194
[ 11.658231]
[ 11.658231] -> #1 (&port_lock_key){....}-{2:2}:
[ 11.658246] _raw_spin_lock+0x48/0x60
[ 11.658254] pl011_console_write+0x150/0x1c4
[ 11.658261] console_flush_all+0x20c/0x510
[ 11.658269] console_unlock+0x6c/0x144
[ 11.658277] vprintk_emit+0x22c/0x3bc
[ 11.658285] vprintk_default+0x38/0x44
[ 11.658294] vprintk+0xa4/0xc0
[ 11.658302] _printk+0x5c/0x84
[ 11.658309] register_console+0x1f4/0x420
[ 11.658316] serial_core_register_port+0x5a0/0x5d4
[ 11.658325] serial_ctrl_register_port+0x10/0x1c
[ 11.658333] uart_add_one_port+0x10/0x1c
[ 11.658341] pl011_register_port+0x70/0x12c
[ 11.658348] pl011_probe+0x1ac/0x1e0
[ 11.658355] amba_probe+0x110/0x1c4
[ 11.658363] really_probe+0x148/0x2ac
[ 11.658370] __driver_probe_device+0x78/0x12c
[ 11.658377] driver_probe_device+0x3c/0x10c
[ 11.658385] __device_attach_driver+0xb8/0xf8
[ 11.658392] bus_for_each_drv+0x80/0xdc
[ 11.658399] __device_attach+0xa8/0x1b0
[ 11.658406] device_initial_probe+0x14/0x20
[ 11.658413] bus_probe_device+0xb0/0xb4
[ 11.658420] device_add+0x5c8/0x784
[ 11.658429] amba_device_add+0x40/0xac
[ 11.658437] of_platform_bus_create+0x2b4/0x378
[ 11.658444] of_platform_populate+0x50/0xfc
[ 11.658450] of_platform_default_populate_init+0xd0/0xf0
[ 11.658459] do_one_initcall+0x74/0x2f0
[ 11.658466] kernel_init_freeable+0x2a0/0x4f8
[ 11.658473] kernel_init+0x24/0x1e0
[ 11.658482] ret_from_fork+0x10/0x20
[ 11.658489]
[ 11.658489] -> #0 (console_owner){....}-{0:0}:
[ 11.658504] __lock_acquire+0x1510/0x1ff0
[ 11.658512] lock_acquire+0x1f0/0x330
[ 11.658519] console_flush_all+0x1f8/0x510
[ 11.658527] console_unlock+0x6c/0x144
[ 11.658535] vprintk_emit+0x22c/0x3bc
[ 11.658542] vprintk_default+0x38/0x44
[ 11.658550] vprintk+0xa4/0xc0
[ 11.658558] _printk+0x5c/0x84
[ 11.658565] lookup_object_or_alloc.part.0+0x150/0x2a8
[ 11.658574] __debug_object_init+0x108/0x20c
[ 11.658582] debug_object_init+0x24/0x30
[ 11.658591] __init_work+0x34/0x40
[ 11.658599] rhashtable_init+0x10c/0x2a8
[ 11.658608] bch2_copygc_thread+0x50/0x474
[ 11.658617] kthread+0x124/0x128
[ 11.658625] ret_from_fork+0x10/0x20
[ 11.658636]
[ 11.658636] other info that might help us debug this:
[ 11.658636]
[ 11.658671] Chain exists of:
[ 11.658671] console_owner --> &pool->lock --> &obj_hash[i].lock
[ 11.658671]
[ 11.658709] Possible unsafe locking scenario:
[ 11.658709]
[ 11.658714] CPU0 CPU1
[ 11.658719] ---- ----
[ 11.658727] lock(&obj_hash[i].lock);
[ 11.658743] lock(&pool->lock);
[ 11.658759] lock(&obj_hash[i].lock);
[ 11.658780] lock(console_owner);
[ 11.658798]
[ 11.658798] *** DEADLOCK ***
[ 11.658798]
[ 11.658821] 3 locks held by bch-copygc/nvme/790:
[ 11.658843] #0: ffffac9251375218 (&obj_hash[i].lock){-.-.}-{2:2}, at: __debug_object_init+0xac/0x20c
[ 11.658880] #1: ffffac9250236870 (console_lock){+.+.}-{0:0}, at: vprintk_emit+0x11c/0x3bc
[ 11.658923] #2: ffffac9250236908 (console_srcu){....}-{0:0}, at: console_flush_all+0x7c/0x510
[ 11.658958]
[ 11.658958] stack backtrace:
[ 11.659058] CPU: 3 PID: 790 Comm: bch-copygc/nvme Tainted: G N 6.6.0-03474-gcd063c8b9e1e #1
[ 11.659081] Hardware name: linux,dummy-virt (DT)
[ 11.659202] Call trace:
[ 11.659214] dump_backtrace+0x94/0xec
[ 11.659241] show_stack+0x18/0x24
[ 11.659248] dump_stack_lvl+0x74/0xd4
[ 11.659257] dump_stack+0x18/0x24
[ 11.659265] print_circular_bug+0x290/0x370
[ 11.659273] check_noncircular+0x184/0x198
[ 11.659281] __lock_acquire+0x1510/0x1ff0
[ 11.659288] lock_acquire+0x1f0/0x330
[ 11.659296] console_flush_all+0x1f8/0x510
[ 11.659304] console_unlock+0x6c/0x144
[ 11.659312] vprintk_emit+0x22c/0x3bc
[ 11.659320] vprintk_default+0x38/0x44
[ 11.659328] vprintk+0xa4/0xc0
[ 11.659336] _printk+0x5c/0x84
[ 11.659344] lookup_object_or_alloc.part.0+0x150/0x2a8
[ 11.659353] __debug_object_init+0x108/0x20c
[ 11.659362] debug_object_init+0x24/0x30
[ 11.659370] __init_work+0x34/0x40
[ 11.659379] rhashtable_init+0x10c/0x2a8
[ 11.659387] bch2_copygc_thread+0x50/0x474
[ 11.659394] kthread+0x124/0x128
[ 11.659402] ret_from_fork+0x10/0x20
[ 11.668336] ------------[ cut here ]------------
[ 11.668466] WARNING: CPU: 3 PID: 790 at lib/debugobjects.c:557 lookup_object_or_alloc.part.0+0x100/0x2a8
[ 11.668592] Modules linked in:
[ 11.668708] CPU: 3 PID: 790 Comm: bch-copygc/nvme Tainted: G N 6.6.0-03474-gcd063c8b9e1e #1
[ 11.668802] Hardware name: linux,dummy-virt (DT)
[ 11.668890] pstate: 600000c5 (nZCv daIF -PAN -UAO -TCO -DIT -SSBS BTYPE=--)
[ 11.668979] pc : lookup_object_or_alloc.part.0+0x100/0x2a8
[ 11.669045] lr : lookup_object_or_alloc.part.0+0x150/0x2a8
[ 11.669113] sp : ffff80008164b950
[ 11.669176] x29: ffff80008164b950 x28: ffffac9250213ea8 x27: 0000000000000000
[ 11.669304] x26: 0000000000000000 x25: ffff80008164bb80 x24: ffffac92513751f8
[ 11.669393] x23: ffffac925131f0b0 x22: 0000000000000000 x21: ffffac924e97c620
[ 11.669478] x20: ffff0f04c6942248 x19: ffff0f04dfcd17b0 x18: ffffffffffffffff
[ 11.669575] x17: 2020202020202020 x16: 2020202020202020 x15: ffff80010164b577
[ 11.669686] x14: 0000000000000000 x13: ffffac9250236af8 x12: 0000000000000ed9
[ 11.669777] x11: 00000000000004f3 x10: ffffac925028eaf8 x9 : ffffac9250236af8
[ 11.669885] x8 : 00000000ffffefff x7 : ffffac925028eaf8 x6 : 0000000000000000
[ 11.669969] x5 : ffff0f04dfcc1f88 x4 : 0000000000000000 x3 : 0000000000000000
[ 11.670054] x2 : 0000000000000000 x1 : ffff0f04c6f38040 x0 : 0000000000000050
[ 11.670159] Call trace:
[ 11.670206] lookup_object_or_alloc.part.0+0x100/0x2a8
[ 11.670265] __debug_object_init+0x108/0x20c
[ 11.670315] debug_object_init+0x24/0x30
[ 11.670362] __init_work+0x34/0x40
[ 11.670406] rhashtable_init+0x10c/0x2a8
[ 11.670452] bch2_copygc_thread+0x50/0x474
[ 11.670499] kthread+0x124/0x128
[ 11.670560] ret_from_fork+0x10/0x20
[ 11.670659] irq event stamp: 20
[ 11.670705] hardirqs last enabled at (19): [<ffffac924e046454>] get_random_u32+0x1e0/0x220
[ 11.670795] hardirqs last disabled at (20): [<ffffac924e94a130>] _raw_spin_lock_irqsave+0x84/0x88
[ 11.670897] softirqs last enabled at (0): [<ffffac924d29b324>] copy_process+0x670/0x19d8
[ 11.670989] softirqs last disabled at (0): [<0000000000000000>] 0x0
[ 11.671258] ---[ end trace 0000000000000000 ]---
^ permalink raw reply [flat|nested] 3+ messages in thread* Re: odebuf and lockdep splat with bcachefs 2023-10-31 3:07 odebuf and lockdep splat with bcachefs Guenter Roeck @ 2023-10-31 14:11 ` Brian Foster 2023-10-31 14:44 ` Guenter Roeck 0 siblings, 1 reply; 3+ messages in thread From: Brian Foster @ 2023-10-31 14:11 UTC (permalink / raw) To: Guenter Roeck; +Cc: linux-bcachefs, Kent Overstreet On Mon, Oct 30, 2023 at 08:07:17PM -0700, Guenter Roeck wrote: > Hi, > > when trying the new bcachefs in the mainline kernel, I see the > attached ODEBUG and lockdep splats. > > This is simply mounting an empty bcachefs file system and > copying some files into it. > Hi Guenter, I reproduce fairly quickly with DEBUG_OBJECTS_WORK enabled. It looks to me that the lockdep splat is essentially fallout from the subsequent warning, which doesn't like the INIT_WORK() of the onstack rhashtable. Ideally this could INIT_WORK_ONSTACK(), but I don't see support for that plumbed through the rhashtable interface. Given this is the main copygc task fn, it seems fairly reasonable to me to just slab alloc the whole bucket tracking structure (as below). This addresses the splat for me on a quick test. Kent, Let me know if you're good with this and I'll post a proper patch.. Brian --- 8< --- diff --git a/fs/bcachefs/movinggc.c b/fs/bcachefs/movinggc.c index 4017120baeee..b835b85ef8b9 100644 --- a/fs/bcachefs/movinggc.c +++ b/fs/bcachefs/movinggc.c @@ -304,14 +304,16 @@ static int bch2_copygc_thread(void *arg) struct moving_context ctxt; struct bch_move_stats move_stats; struct io_clock *clock = &c->io_clock[WRITE]; - struct buckets_in_flight buckets; + struct buckets_in_flight *buckets; u64 last, wait; int ret = 0; - memset(&buckets, 0, sizeof(buckets)); - - ret = rhashtable_init(&buckets.table, &bch_move_bucket_params); + buckets = kzalloc(sizeof(struct buckets_in_flight), GFP_KERNEL); + if (!buckets) + return -ENOMEM; + ret = rhashtable_init(&buckets->table, &bch_move_bucket_params); if (ret) { + kfree(buckets); bch_err_msg(c, ret, "allocating copygc buckets in flight"); return ret; } @@ -329,12 +331,12 @@ static int bch2_copygc_thread(void *arg) cond_resched(); if (!c->copy_gc_enabled) { - move_buckets_wait(trans, &ctxt, &buckets, true); + move_buckets_wait(trans, &ctxt, buckets, true); kthread_wait_freezable(c->copy_gc_enabled); } if (unlikely(freezing(current))) { - move_buckets_wait(trans, &ctxt, &buckets, true); + move_buckets_wait(trans, &ctxt, buckets, true); __refrigerator(false); continue; } @@ -345,7 +347,7 @@ static int bch2_copygc_thread(void *arg) if (wait > clock->max_slop) { c->copygc_wait_at = last; c->copygc_wait = last + wait; - move_buckets_wait(trans, &ctxt, &buckets, true); + move_buckets_wait(trans, &ctxt, buckets, true); trace_and_count(c, copygc_wait, c, wait, last + wait); bch2_kthread_io_clock_wait(clock, last + wait, MAX_SCHEDULE_TIMEOUT); @@ -355,14 +357,16 @@ static int bch2_copygc_thread(void *arg) c->copygc_wait = 0; c->copygc_running = true; - ret = bch2_copygc(trans, &ctxt, &buckets); + ret = bch2_copygc(trans, &ctxt, buckets); c->copygc_running = false; wake_up(&c->copygc_running_wq); } - move_buckets_wait(trans, &ctxt, &buckets, true); - rhashtable_destroy(&buckets.table); + move_buckets_wait(trans, &ctxt, buckets, true); + + rhashtable_destroy(&buckets->table); + kfree(buckets); bch2_trans_put(trans); bch2_moving_ctxt_exit(&ctxt); ^ permalink raw reply related [flat|nested] 3+ messages in thread
* Re: odebuf and lockdep splat with bcachefs 2023-10-31 14:11 ` Brian Foster @ 2023-10-31 14:44 ` Guenter Roeck 0 siblings, 0 replies; 3+ messages in thread From: Guenter Roeck @ 2023-10-31 14:44 UTC (permalink / raw) To: Brian Foster; +Cc: linux-bcachefs, Kent Overstreet On 10/31/23 07:11, Brian Foster wrote: > On Mon, Oct 30, 2023 at 08:07:17PM -0700, Guenter Roeck wrote: >> Hi, >> >> when trying the new bcachefs in the mainline kernel, I see the >> attached ODEBUG and lockdep splats. >> >> This is simply mounting an empty bcachefs file system and >> copying some files into it. >> > > Hi Guenter, > > I reproduce fairly quickly with DEBUG_OBJECTS_WORK enabled. It looks to > me that the lockdep splat is essentially fallout from the subsequent > warning, which doesn't like the INIT_WORK() of the onstack rhashtable. > Ideally this could INIT_WORK_ONSTACK(), but I don't see support for that > plumbed through the rhashtable interface. Given this is the main copygc > task fn, it seems fairly reasonable to me to just slab alloc the whole > bucket tracking structure (as below). This addresses the splat for me on > a quick test. > The patch below fixes the problem for me. Tested-by: Guenter Roeck <linux@roeck-us.net> Tested with arm64 qemu, both little and big endian. Thanks, Guenter > Kent, > > Let me know if you're good with this and I'll post a proper patch.. > > Brian > > --- 8< --- > > diff --git a/fs/bcachefs/movinggc.c b/fs/bcachefs/movinggc.c > index 4017120baeee..b835b85ef8b9 100644 > --- a/fs/bcachefs/movinggc.c > +++ b/fs/bcachefs/movinggc.c > @@ -304,14 +304,16 @@ static int bch2_copygc_thread(void *arg) > struct moving_context ctxt; > struct bch_move_stats move_stats; > struct io_clock *clock = &c->io_clock[WRITE]; > - struct buckets_in_flight buckets; > + struct buckets_in_flight *buckets; > u64 last, wait; > int ret = 0; > > - memset(&buckets, 0, sizeof(buckets)); > - > - ret = rhashtable_init(&buckets.table, &bch_move_bucket_params); > + buckets = kzalloc(sizeof(struct buckets_in_flight), GFP_KERNEL); > + if (!buckets) > + return -ENOMEM; > + ret = rhashtable_init(&buckets->table, &bch_move_bucket_params); > if (ret) { > + kfree(buckets); > bch_err_msg(c, ret, "allocating copygc buckets in flight"); > return ret; > } > @@ -329,12 +331,12 @@ static int bch2_copygc_thread(void *arg) > cond_resched(); > > if (!c->copy_gc_enabled) { > - move_buckets_wait(trans, &ctxt, &buckets, true); > + move_buckets_wait(trans, &ctxt, buckets, true); > kthread_wait_freezable(c->copy_gc_enabled); > } > > if (unlikely(freezing(current))) { > - move_buckets_wait(trans, &ctxt, &buckets, true); > + move_buckets_wait(trans, &ctxt, buckets, true); > __refrigerator(false); > continue; > } > @@ -345,7 +347,7 @@ static int bch2_copygc_thread(void *arg) > if (wait > clock->max_slop) { > c->copygc_wait_at = last; > c->copygc_wait = last + wait; > - move_buckets_wait(trans, &ctxt, &buckets, true); > + move_buckets_wait(trans, &ctxt, buckets, true); > trace_and_count(c, copygc_wait, c, wait, last + wait); > bch2_kthread_io_clock_wait(clock, last + wait, > MAX_SCHEDULE_TIMEOUT); > @@ -355,14 +357,16 @@ static int bch2_copygc_thread(void *arg) > c->copygc_wait = 0; > > c->copygc_running = true; > - ret = bch2_copygc(trans, &ctxt, &buckets); > + ret = bch2_copygc(trans, &ctxt, buckets); > c->copygc_running = false; > > wake_up(&c->copygc_running_wq); > } > > - move_buckets_wait(trans, &ctxt, &buckets, true); > - rhashtable_destroy(&buckets.table); > + move_buckets_wait(trans, &ctxt, buckets, true); > + > + rhashtable_destroy(&buckets->table); > + kfree(buckets); > bch2_trans_put(trans); > bch2_moving_ctxt_exit(&ctxt); > ^ permalink raw reply [flat|nested] 3+ messages in thread
end of thread, other threads:[~2023-10-31 14:45 UTC | newest] Thread overview: 3+ messages (download: mbox.gz follow: Atom feed -- links below jump to the message on this page -- 2023-10-31 3:07 odebuf and lockdep splat with bcachefs Guenter Roeck 2023-10-31 14:11 ` Brian Foster 2023-10-31 14:44 ` Guenter Roeck
This is an external index of several public inboxes, see mirroring instructions on how to clone and mirror all data and code used by this external index.