Received-SPF: pass (google.com: best guess record for domain of linux-kernel-owner@vger.kernel.org designates 209.132.180.67 as permitted sender) client-ip=209.132.180.67;
Content-Type: text/plain;
        charset=us-ascii
Mime-Version: 1.0 (Mac OS X Mail 13.0 \(3601.0.10\))
Subject: Re: [PATCH] char/random: silence a lockdep splat with printk()
From:   Qian Cai <cai@lca.pw>
In-Reply-To: <1573679785-21068-1-git-send-email-cai@lca.pw>
Date:   Tue, 3 Dec 2019 13:46:01 -0500
Cc:     Arnd Bergmann <arnd@arndb.de>, gregkh@linuxfoundation.org,
        sergey.senozhatsky.work@gmail.com, pmladek@suse.com,
        rostedt@goodmis.org, Catalin Marinas <catalin.marinas@arm.com>,
        will@kernel.org, dan.j.williams@intel.com, peterz@infradead.org,
        longman@redhat.com, tglx@linutronix.de, linux-mm@kvack.org,
        linux-arm-kernel@lists.infradead.org, linux-kernel@vger.kernel.org
Content-Transfer-Encoding: quoted-printable
Message-Id: <637027D4-BBDD-4AA6-B03C-556060988957@lca.pw>
References: <1573679785-21068-1-git-send-email-cai@lca.pw>
To:     tytso@mit.edu
Sender: linux-kernel-owner@vger.kernel.org
Precedence: bulk


> On Nov 13, 2019, at 4:16 PM, Qian Cai <cai@lca.pw> wrote:
>=20
> From: Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com>
>=20
> Sergey didn't like the locking order,
>=20
> uart_port->lock  ->  tty_port->lock
>=20
> 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)
>=20
> 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?

>=20
> 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
>=20
> but task is already holding lock:
> 60ff000822352818 (&pool->lock/1){-.-.}, at: =
start_flush_work+0xd8/0x3f0
>=20
>  which lock already depends on the new lock.
>=20
>  the existing dependency chain (in reverse order) is:
>=20
>  -> #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
>=20
>  -> #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
>=20
>  -> #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
>=20
>  -> #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
>=20
>  -> #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
>=20
>       other info that might help us debug this:
>=20
> Chain exists of:
>   &(&zone->lock)->rlock --> &(&port->lock)->rlock --> &pool->lock/1
>=20
> Possible unsafe locking scenario:
>=20
>       CPU0                    CPU1
>       ----                    ----
>  lock(&pool->lock/1);
>                               lock(&(&port->lock)->rlock);
>                               lock(&pool->lock/1);
>  lock(&(&zone->lock)->rlock);
>=20
>                *** DEADLOCK ***
>=20
> 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
>=20
>               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
>=20
> [cai@lca.pw: add a commit log.]
> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com>
> Signed-off-by: Qian Cai <cai@lca.pw>
> ---
>=20
> Sergey, please let us know if you are fine with the Signed-off-by.
>=20
> drivers/char/random.c | 5 +++--
> 1 file changed, 3 insertions(+), 2 deletions(-)
>=20
> 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 =3D true;
> #endif
> 	if (__ratelimit(&unseeded_warning))
> -		pr_notice("random: %s called from %pS with =
crng_init=3D%d\n",
> -			  func_name, caller, crng_init);
> +		printk_deferred(KERN_NOTICE "random: %s called from %pS =
"
> +				"with crng_init=3D%d\n", func_name, =
caller,
> +				crng_init);
> }
>=20
> /*
> --=20
> 1.8.3.1
>=20