Re: [PATCH] char/random: silence a lockdep splat with printk()

From: Qian Cai
Date: Tue Dec 03 2019 - 13:46:09 EST

Next message: John Stultz: "Re: [PATCH] arm64: mm: Fix initialisation of DMA zones on non-NUMA systems"
Previous message: Sean Christopherson: "Re: [PATCH RFC 04/15] KVM: Implement ring-based dirty memory tracking"
Next in thread: Sergey Senozhatsky: "Re: [PATCH] char/random: silence a lockdep splat with printk()"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

> On Nov 13, 2019, at 4:16 PM, Qian Cai <cai@xxxxxx> wrote:
>
> From: Sergey Senozhatsky <sergey.senozhatsky.work@xxxxxxxxx>
>
> Sergey didn't like the locking order,
>
> uart_port->lock -> tty_port->lock
>
> uart_write (uart_port->lock)
> __uart_start
> pl011_start_tx
> pl011_tx_chars
> uart_write_wakeup
> tty_port_tty_wakeup
> tty_port_default
> tty_port_tty_get (tty_port->lock)
>
> but those code is so old, and I have no clue how to de-couple it after
> checking other locks in the splat. There is an onging effort to make all
> printk() as deferred, so until that happens, workaround it for now as a
> short-term fix.

Sergey, could we have a ACK from you so Ted might be able to merge?

>
> LTP: starting iogen01 (export LTPROOT; rwtest -N iogen01 -i 120s -s
> read,write -Da -Dv -n 2 500b:$TMPDIR/doio.f1.$$
> 1000b:$TMPDIR/doio.f2.$$)
> WARNING: possible circular locking dependency detected
> ------------------------------------------------------
> doio/49441 is trying to acquire lock:
> ffff008b7cff7290 (&(&zone->lock)->rlock){..-.}, at: rmqueue+0x138/0x2050
>
> but task is already holding lock:
> 60ff000822352818 (&pool->lock/1){-.-.}, at: start_flush_work+0xd8/0x3f0
>
> which lock already depends on the new lock.
>
> the existing dependency chain (in reverse order) is:
>
> -> #4 (&pool->lock/1){-.-.}:
> lock_acquire+0x320/0x360
> _raw_spin_lock+0x64/0x80
> __queue_work+0x4b4/0xa10
> queue_work_on+0xac/0x11c
> tty_schedule_flip+0x84/0xbc
> tty_flip_buffer_push+0x1c/0x28
> pty_write+0x98/0xd0
> n_tty_write+0x450/0x60c
> tty_write+0x338/0x474
> __vfs_write+0x88/0x214
> vfs_write+0x12c/0x1a4
> redirected_tty_write+0x90/0xdc
> do_loop_readv_writev+0x140/0x180
> do_iter_write+0xe0/0x10c
> vfs_writev+0x134/0x1cc
> do_writev+0xbc/0x130
> __arm64_sys_writev+0x58/0x8c
> el0_svc_handler+0x170/0x240
> el0_sync_handler+0x150/0x250
> el0_sync+0x164/0x180
>
> -> #3 (&(&port->lock)->rlock){-.-.}:
> lock_acquire+0x320/0x360
> _raw_spin_lock_irqsave+0x7c/0x9c
> tty_port_tty_get+0x24/0x60
> tty_port_default_wakeup+0x1c/0x3c
> tty_port_tty_wakeup+0x34/0x40
> uart_write_wakeup+0x28/0x44
> pl011_tx_chars+0x1b8/0x270
> pl011_start_tx+0x24/0x70
> __uart_start+0x5c/0x68
> uart_write+0x164/0x1c8
> do_output_char+0x33c/0x348
> n_tty_write+0x4bc/0x60c
> tty_write+0x338/0x474
> redirected_tty_write+0xc0/0xdc
> do_loop_readv_writev+0x140/0x180
> do_iter_write+0xe0/0x10c
> vfs_writev+0x134/0x1cc
> do_writev+0xbc/0x130
> __arm64_sys_writev+0x58/0x8c
> el0_svc_handler+0x170/0x240
> el0_sync_handler+0x150/0x250
> el0_sync+0x164/0x180
>
> -> #2 (&port_lock_key){-.-.}:
> lock_acquire+0x320/0x360
> _raw_spin_lock+0x64/0x80
> pl011_console_write+0xec/0x2cc
> console_unlock+0x794/0x96c
> vprintk_emit+0x260/0x31c
> vprintk_default+0x54/0x7c
> vprintk_func+0x218/0x254
> printk+0x7c/0xa4
> register_console+0x734/0x7b0
> uart_add_one_port+0x734/0x834
> pl011_register_port+0x6c/0xac
> sbsa_uart_probe+0x234/0x2ec
> platform_drv_probe+0xd4/0x124
> really_probe+0x250/0x71c
> driver_probe_device+0xb4/0x200
> __device_attach_driver+0xd8/0x188
> bus_for_each_drv+0xbc/0x110
> __device_attach+0x120/0x220
> device_initial_probe+0x20/0x2c
> bus_probe_device+0x54/0x100
> device_add+0xae8/0xc2c
> platform_device_add+0x278/0x3b8
> platform_device_register_full+0x238/0x2ac
> acpi_create_platform_device+0x2dc/0x3a8
> acpi_bus_attach+0x390/0x3cc
> acpi_bus_attach+0x108/0x3cc
> acpi_bus_attach+0x108/0x3cc
> acpi_bus_attach+0x108/0x3cc
> acpi_bus_scan+0x7c/0xb0
> acpi_scan_init+0xe4/0x304
> acpi_init+0x100/0x114
> do_one_initcall+0x348/0x6a0
> do_initcall_level+0x190/0x1fc
> do_basic_setup+0x34/0x4c
> kernel_init_freeable+0x19c/0x260
> kernel_init+0x18/0x338
> ret_from_fork+0x10/0x18
>
> -> #1 (console_owner){-...}:
> lock_acquire+0x320/0x360
> console_lock_spinning_enable+0x6c/0x7c
> console_unlock+0x4f8/0x96c
> vprintk_emit+0x260/0x31c
> vprintk_default+0x54/0x7c
> vprintk_func+0x218/0x254
> printk+0x7c/0xa4
> get_random_u64+0x1c4/0x1dc
> shuffle_pick_tail+0x40/0xac
> __free_one_page+0x424/0x710
> free_one_page+0x70/0x120
> __free_pages_ok+0x61c/0xa94
> __free_pages_core+0x1bc/0x294
> memblock_free_pages+0x38/0x48
> __free_pages_memory+0xcc/0xfc
> __free_memory_core+0x70/0x78
> free_low_memory_core_early+0x148/0x18c
> memblock_free_all+0x18/0x54
> mem_init+0xb4/0x17c
> mm_init+0x14/0x38
> start_kernel+0x19c/0x530
>
> -> #0 (&(&zone->lock)->rlock){..-.}:
> validate_chain+0xf6c/0x2e2c
> __lock_acquire+0x868/0xc2c
> lock_acquire+0x320/0x360
> _raw_spin_lock+0x64/0x80
> rmqueue+0x138/0x2050
> get_page_from_freelist+0x474/0x688
> __alloc_pages_nodemask+0x3b4/0x18dc
> alloc_pages_current+0xd0/0xe0
> alloc_slab_page+0x2b4/0x5e0
> new_slab+0xc8/0x6bc
> ___slab_alloc+0x3b8/0x640
> kmem_cache_alloc+0x4b4/0x588
> __debug_object_init+0x778/0x8b4
> debug_object_init_on_stack+0x40/0x50
> start_flush_work+0x16c/0x3f0
> __flush_work+0xb8/0x124
> flush_work+0x20/0x30
> xlog_cil_force_lsn+0x88/0x204 [xfs]
> xfs_log_force_lsn+0x128/0x1b8 [xfs]
> xfs_file_fsync+0x3c4/0x488 [xfs]
> vfs_fsync_range+0xb0/0xd0
> generic_write_sync+0x80/0xa0 [xfs]
> xfs_file_buffered_aio_write+0x66c/0x6e4 [xfs]
> xfs_file_write_iter+0x1a0/0x218 [xfs]
> __vfs_write+0x1cc/0x214
> vfs_write+0x12c/0x1a4
> ksys_write+0xb0/0x120
> __arm64_sys_write+0x54/0x88
> el0_svc_handler+0x170/0x240
> el0_sync_handler+0x150/0x250
> el0_sync+0x164/0x180
>
> other info that might help us debug this:
>
> Chain exists of:
> &(&zone->lock)->rlock --> &(&port->lock)->rlock --> &pool->lock/1
>
> Possible unsafe locking scenario:
>
> CPU0 CPU1
> ---- ----
> lock(&pool->lock/1);
> lock(&(&port->lock)->rlock);
> lock(&pool->lock/1);
> lock(&(&zone->lock)->rlock);
>
> *** DEADLOCK ***
>
> 4 locks held by doio/49441:
> #0: a0ff00886fc27408 (sb_writers#8){.+.+}, at: vfs_write+0x118/0x1a4
> #1: 8fff00080810dfe0 (&xfs_nondir_ilock_class){++++}, at:
> xfs_ilock+0x2a8/0x300 [xfs]
> #2: ffff9000129f2390 (rcu_read_lock){....}, at:
> rcu_lock_acquire+0x8/0x38
> #3: 60ff000822352818 (&pool->lock/1){-.-.}, at:
> start_flush_work+0xd8/0x3f0
>
> stack backtrace:
> CPU: 48 PID: 49441 Comm: doio Tainted: G W
> Hardware name: HPE Apollo 70 /C01_APACHE_MB , BIOS
> L50_5.13_1.11 06/18/2019
> Call trace:
> dump_backtrace+0x0/0x248
> show_stack+0x20/0x2c
> dump_stack+0xe8/0x150
> print_circular_bug+0x368/0x380
> check_noncircular+0x28c/0x294
> validate_chain+0xf6c/0x2e2c
> __lock_acquire+0x868/0xc2c
> lock_acquire+0x320/0x360
> _raw_spin_lock+0x64/0x80
> rmqueue+0x138/0x2050
> get_page_from_freelist+0x474/0x688
> __alloc_pages_nodemask+0x3b4/0x18dc
> alloc_pages_current+0xd0/0xe0
> alloc_slab_page+0x2b4/0x5e0
> new_slab+0xc8/0x6bc
> ___slab_alloc+0x3b8/0x640
> kmem_cache_alloc+0x4b4/0x588
> __debug_object_init+0x778/0x8b4
> debug_object_init_on_stack+0x40/0x50
> start_flush_work+0x16c/0x3f0
> __flush_work+0xb8/0x124
> flush_work+0x20/0x30
> xlog_cil_force_lsn+0x88/0x204 [xfs]
> xfs_log_force_lsn+0x128/0x1b8 [xfs]
> xfs_file_fsync+0x3c4/0x488 [xfs]
> vfs_fsync_range+0xb0/0xd0
> generic_write_sync+0x80/0xa0 [xfs]
> xfs_file_buffered_aio_write+0x66c/0x6e4 [xfs]
> xfs_file_write_iter+0x1a0/0x218 [xfs]
> __vfs_write+0x1cc/0x214
> vfs_write+0x12c/0x1a4
> ksys_write+0xb0/0x120
> __arm64_sys_write+0x54/0x88
> el0_svc_handler+0x170/0x240
> el0_sync_handler+0x150/0x250
> el0_sync+0x164/0x180
>
> [cai@xxxxxx: add a commit log.]
> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky.work@xxxxxxxxx>
> Signed-off-by: Qian Cai <cai@xxxxxx>
> ---
>
> Sergey, please let us know if you are fine with the Signed-off-by.
>
> drivers/char/random.c | 5 +++--
> 1 file changed, 3 insertions(+), 2 deletions(-)
>
> diff --git a/drivers/char/random.c b/drivers/char/random.c
> index 46afd14facb7..b90086c9836f 100644
> --- a/drivers/char/random.c
> +++ b/drivers/char/random.c
> @@ -1688,8 +1688,9 @@ static void _warn_unseeded_randomness(const char *func_name, void *caller,
> print_once = true;
> #endif
> if (__ratelimit(&unseeded_warning))
> - pr_notice("random: %s called from %pS with crng_init=%d\n",
> - func_name, caller, crng_init);
> + printk_deferred(KERN_NOTICE "random: %s called from %pS "
> + "with crng_init=%d\n", func_name, caller,
> + crng_init);
> }
>
> /*
> --
> 1.8.3.1
>

Next message: John Stultz: "Re: [PATCH] arm64: mm: Fix initialisation of DMA zones on non-NUMA systems"
Previous message: Sean Christopherson: "Re: [PATCH RFC 04/15] KVM: Implement ring-based dirty memory tracking"
Next in thread: Sergey Senozhatsky: "Re: [PATCH] char/random: silence a lockdep splat with printk()"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]