printk() + memory offline deadlock (WAS Re: page_alloc.shuffle=1 + CONFIG_PROVE_LOCKING=y = arm64 hang)

[Qian Cai]

On Mon, 2019-09-16 at 10:42 -0400, Steven Rostedt wrote:
> On Thu, 12 Sep 2019 08:05:41 -0400
> Qian Cai <cai@xxxxxx> wrote:
> 
> > >  drivers/char/random.c | 7 ++++---
> > >  1 file changed, 4 insertions(+), 3 deletions(-)
> > > 
> > > diff --git a/drivers/char/random.c b/drivers/char/random.c
> > > index 9b54cdb301d3..975015857200 100644
> > > --- a/drivers/char/random.c
> > > +++ b/drivers/char/random.c
> > > @@ -1687,8 +1687,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);
> > >  }
> > >  
> > >  /*
> > > @@ -2462,4 +2463,4 @@ void add_bootloader_randomness(const void *buf, unsigned int size)
> > >  	else
> > >  		add_device_randomness(buf, size);
> > >  }
> > > -EXPORT_SYMBOL_GPL(add_bootloader_randomness);
> > > \ No newline at end of file
> > > +EXPORT_SYMBOL_GPL(add_bootloader_randomness);  
> > 
> > This will also fix the hang.
> > 
> > Sergey, do you plan to submit this Ted?
> 
> Perhaps for a quick fix (and a comment that says this needs to be fixed
> properly). I think the changes to printk() that was discussed at
> Plumbers may also solve this properly.

I assume that the new printk() stuff will also fix this deadlock between
printk() and memory offline.

[ÂÂ317.337595] WARNING: possible circular locking dependency detected
[ÂÂ317.337596] 5.3.0-next-20190917+ #9 Not tainted
[ÂÂ317.337597] ------------------------------------------------------
[ÂÂ317.337597] test.sh/8738 is trying to acquire lock:
[ÂÂ317.337598] ffffffffb33a4978 ((console_sem).lock){-.-.}, at:
down_trylock+0x16/0x50

[ÂÂ317.337602] but task is already holding lock:
[ÂÂ317.337602] ffff88883fff4318 (&(&zone->lock)->rlock){-.-.}, at:
start_isolate_page_range+0x1f7/0x570

[ÂÂ317.337606] which lock already depends on the new lock.


[ÂÂ317.337608] the existing dependency chain (in reverse order) is:

[ÂÂ317.337609] -> #3 (&(&zone->lock)->rlock){-.-.}:
[ÂÂ317.337612]ÂÂÂÂÂÂÂÂ__lock_acquire+0x5b3/0xb40
[ÂÂ317.337613]ÂÂÂÂÂÂÂÂlock_acquire+0x126/0x280
[ÂÂ317.337613]ÂÂÂÂÂÂÂÂ_raw_spin_lock+0x2f/0x40
[ÂÂ317.337614]ÂÂÂÂÂÂÂÂrmqueue_bulk.constprop.21+0xb6/0x1160
[ÂÂ317.337615]ÂÂÂÂÂÂÂÂget_page_from_freelist+0x898/0x22c0
[ÂÂ317.337616]ÂÂÂÂÂÂÂÂ__alloc_pages_nodemask+0x2f3/0x1cd0
[ÂÂ317.337617]ÂÂÂÂÂÂÂÂalloc_page_interleave+0x18/0x130
[ÂÂ317.337618]ÂÂÂÂÂÂÂÂalloc_pages_current+0xf6/0x110
[ÂÂ317.337619]ÂÂÂÂÂÂÂÂallocate_slab+0x4c6/0x19c0
[ÂÂ317.337620]ÂÂÂÂÂÂÂÂnew_slab+0x46/0x70
[ÂÂ317.337621]ÂÂÂÂÂÂÂÂ___slab_alloc+0x58b/0x960
[ÂÂ317.337621]ÂÂÂÂÂÂÂÂ__slab_alloc+0x43/0x70
[ÂÂ317.337622]ÂÂÂÂÂÂÂÂkmem_cache_alloc+0x354/0x460
[ÂÂ317.337623]ÂÂÂÂÂÂÂÂfill_pool+0x272/0x4b0
[ÂÂ317.337624]ÂÂÂÂÂÂÂÂ__debug_object_init+0x86/0x790
[ÂÂ317.337624]ÂÂÂÂÂÂÂÂdebug_object_init+0x16/0x20
[ÂÂ317.337625]ÂÂÂÂÂÂÂÂhrtimer_init+0x27/0x1e0
[ÂÂ317.337626]ÂÂÂÂÂÂÂÂinit_dl_task_timer+0x20/0x40
[ÂÂ317.337627]ÂÂÂÂÂÂÂÂ__sched_fork+0x10b/0x1f0
[ÂÂ317.337627]ÂÂÂÂÂÂÂÂinit_idle+0xac/0x520
[ÂÂ317.337628]ÂÂÂÂÂÂÂÂidle_thread_get+0x7c/0xc0
[ÂÂ317.337629]ÂÂÂÂÂÂÂÂbringup_cpu+0x1a/0x1e0
[ÂÂ317.337630]ÂÂÂÂÂÂÂÂcpuhp_invoke_callback+0x197/0x1120
[ÂÂ317.337630]ÂÂÂÂÂÂÂÂ_cpu_up+0x171/0x280
[ÂÂ317.337631]ÂÂÂÂÂÂÂÂdo_cpu_up+0xb1/0x120
[ÂÂ317.337632]ÂÂÂÂÂÂÂÂcpu_up+0x13/0x20
[ÂÂ317.337632]ÂÂÂÂÂÂÂÂsmp_init+0xa4/0x12d
[ÂÂ317.337633]ÂÂÂÂÂÂÂÂkernel_init_freeable+0x37e/0x76e
[ÂÂ317.337634]ÂÂÂÂÂÂÂÂkernel_init+0x11/0x12f
[ÂÂ317.337635]ÂÂÂÂÂÂÂÂret_from_fork+0x3a/0x50

[ÂÂ317.337635] -> #2 (&rq->lock){-.-.}:
[ÂÂ317.337638]ÂÂÂÂÂÂÂÂ__lock_acquire+0x5b3/0xb40
[ÂÂ317.337639]ÂÂÂÂÂÂÂÂlock_acquire+0x126/0x280
[ÂÂ317.337639]ÂÂÂÂÂÂÂÂ_raw_spin_lock+0x2f/0x40
[ÂÂ317.337640]ÂÂÂÂÂÂÂÂtask_fork_fair+0x43/0x200
[ÂÂ317.337641]ÂÂÂÂÂÂÂÂsched_fork+0x29b/0x420
[ÂÂ317.337642]ÂÂÂÂÂÂÂÂcopy_process+0xf3c/0x2fd0
[ÂÂ317.337642]ÂÂÂÂÂÂÂÂ_do_fork+0xef/0x950
[ÂÂ317.337643]ÂÂÂÂÂÂÂÂkernel_thread+0xa8/0xe0
[ÂÂ317.337644]ÂÂÂÂÂÂÂÂrest_init+0x28/0x311
[ÂÂ317.337645]ÂÂÂÂÂÂÂÂarch_call_rest_init+0xe/0x1b
[ÂÂ317.337645]ÂÂÂÂÂÂÂÂstart_kernel+0x6eb/0x724
[ÂÂ317.337646]ÂÂÂÂÂÂÂÂx86_64_start_reservations+0x24/0x26
[ÂÂ317.337647]ÂÂÂÂÂÂÂÂx86_64_start_kernel+0xf4/0xfb
[ÂÂ317.337648]ÂÂÂÂÂÂÂÂsecondary_startup_64+0xb6/0xc0

[ÂÂ317.337649] -> #1 (&p->pi_lock){-.-.}:
[ÂÂ317.337651]ÂÂÂÂÂÂÂÂ__lock_acquire+0x5b3/0xb40
[ÂÂ317.337652]ÂÂÂÂÂÂÂÂlock_acquire+0x126/0x280
[ÂÂ317.337653]ÂÂÂÂÂÂÂÂ_raw_spin_lock_irqsave+0x3a/0x50
[ÂÂ317.337653]ÂÂÂÂÂÂÂÂtry_to_wake_up+0xb4/0x1030
[ÂÂ317.337654]ÂÂÂÂÂÂÂÂwake_up_process+0x15/0x20
[ÂÂ317.337655]ÂÂÂÂÂÂÂÂ__up+0xaa/0xc0
[ÂÂ317.337655]ÂÂÂÂÂÂÂÂup+0x55/0x60
[ÂÂ317.337656]ÂÂÂÂÂÂÂÂ__up_console_sem+0x37/0x60
[ÂÂ317.337657]ÂÂÂÂÂÂÂÂconsole_unlock+0x3a0/0x750
[ÂÂ317.337658]ÂÂÂÂÂÂÂÂvprintk_emit+0x10d/0x340
[ÂÂ317.337658]ÂÂÂÂÂÂÂÂvprintk_default+0x1f/0x30
[ÂÂ317.337659]ÂÂÂÂÂÂÂÂvprintk_func+0x44/0xd4
[ÂÂ317.337660]ÂÂÂÂÂÂÂÂprintk+0x9f/0xc5
[ÂÂ317.337660]ÂÂÂÂÂÂÂÂcrng_reseed+0x3cc/0x440
[ÂÂ317.337661]ÂÂÂÂÂÂÂÂcredit_entropy_bits+0x3e8/0x4f0
[ÂÂ317.337662]ÂÂÂÂÂÂÂÂrandom_ioctl+0x1eb/0x250
[ÂÂ317.337663]ÂÂÂÂÂÂÂÂdo_vfs_ioctl+0x13e/0xa70
[ÂÂ317.337663]ÂÂÂÂÂÂÂÂksys_ioctl+0x41/0x80
[ÂÂ317.337664]ÂÂÂÂÂÂÂÂ__x64_sys_ioctl+0x43/0x4c
[ÂÂ317.337665]ÂÂÂÂÂÂÂÂdo_syscall_64+0xcc/0x76c
[ÂÂ317.337666]ÂÂÂÂÂÂÂÂentry_SYSCALL_64_after_hwframe+0x49/0xbe

[ÂÂ317.337667] -> #0 ((console_sem).lock){-.-.}:
[ÂÂ317.337669]ÂÂÂÂÂÂÂÂcheck_prev_add+0x107/0xea0
[ÂÂ317.337670]ÂÂÂÂÂÂÂÂvalidate_chain+0x8fc/0x1200
[ÂÂ317.337671]ÂÂÂÂÂÂÂÂ__lock_acquire+0x5b3/0xb40
[ÂÂ317.337671]ÂÂÂÂÂÂÂÂlock_acquire+0x126/0x280
[ÂÂ317.337672]ÂÂÂÂÂÂÂÂ_raw_spin_lock_irqsave+0x3a/0x50
[ÂÂ317.337673]ÂÂÂÂÂÂÂÂdown_trylock+0x16/0x50
[ÂÂ317.337674]ÂÂÂÂÂÂÂÂ__down_trylock_console_sem+0x2b/0xa0
[ÂÂ317.337675]ÂÂÂÂÂÂÂÂconsole_trylock+0x16/0x60
[ÂÂ317.337676]ÂÂÂÂÂÂÂÂvprintk_emit+0x100/0x340
[ÂÂ317.337677]ÂÂÂÂÂÂÂÂvprintk_default+0x1f/0x30
[ÂÂ317.337678]ÂÂÂÂÂÂÂÂvprintk_func+0x44/0xd4
[ÂÂ317.337678]ÂÂÂÂÂÂÂÂprintk+0x9f/0xc5
[ÂÂ317.337679]ÂÂÂÂÂÂÂÂ__dump_page.cold.2+0x73/0x210
[ÂÂ317.337680]ÂÂÂÂÂÂÂÂdump_page+0x12/0x50
[ÂÂ317.337680]ÂÂÂÂÂÂÂÂhas_unmovable_pages+0x3e9/0x4b0
[ÂÂ317.337681]ÂÂÂÂÂÂÂÂstart_isolate_page_range+0x3b4/0x570
[ÂÂ317.337682]ÂÂÂÂÂÂÂÂ__offline_pages+0x1ad/0xa10
[ÂÂ317.337683]ÂÂÂÂÂÂÂÂoffline_pages+0x11/0x20
[ÂÂ317.337683]ÂÂÂÂÂÂÂÂmemory_subsys_offline+0x7e/0xc0
[ÂÂ317.337684]ÂÂÂÂÂÂÂÂdevice_offline+0xd5/0x110
[ÂÂ317.337685]ÂÂÂÂÂÂÂÂstate_store+0xc6/0xe0
[ÂÂ317.337686]ÂÂÂÂÂÂÂÂdev_attr_store+0x3f/0x60
[ÂÂ317.337686]ÂÂÂÂÂÂÂÂsysfs_kf_write+0x89/0xb0
[ÂÂ317.337687]ÂÂÂÂÂÂÂÂkernfs_fop_write+0x188/0x240
[ÂÂ317.337688]ÂÂÂÂÂÂÂÂ__vfs_write+0x50/0xa0
[ÂÂ317.337688]ÂÂÂÂÂÂÂÂvfs_write+0x105/0x290
[ÂÂ317.337689]ÂÂÂÂÂÂÂÂksys_write+0xc6/0x160
[ÂÂ317.337690]ÂÂÂÂÂÂÂÂ__x64_sys_write+0x43/0x50
[ÂÂ317.337691]ÂÂÂÂÂÂÂÂdo_syscall_64+0xcc/0x76c
[ÂÂ317.337691]ÂÂÂÂÂÂÂÂentry_SYSCALL_64_after_hwframe+0x49/0xbe

[ÂÂ317.337693] other info that might help us debug this:

[ÂÂ317.337694] Chain exists of:
[ÂÂ317.337694]ÂÂÂ(console_sem).lock --> &rq->lock --> &(&zone->lock)->rlock

[ÂÂ317.337699]ÂÂPossible unsafe locking scenario:

[ÂÂ317.337700]ÂÂÂÂÂÂÂÂCPU0ÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂCPU1
[ÂÂ317.337701]ÂÂÂÂÂÂÂÂ----ÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂ----
[ÂÂ317.337701]ÂÂÂlock(&(&zone->lock)->rlock);
[ÂÂ317.337703]ÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂlock(&rq->lock);
[ÂÂ317.337705]ÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂlock(&(&zone->lock)->rlock);
[ÂÂ317.337706]ÂÂÂlock((console_sem).lock);

[ÂÂ317.337708]ÂÂ*** DEADLOCK ***

[ÂÂ317.337710] 8 locks held by test.sh/8738:
[ÂÂ317.337710]ÂÂ#0: ffff8883940b5408 (sb_writers#4){.+.+}, at:
vfs_write+0x25f/0x290
[ÂÂ317.337713]ÂÂ#1: ffff889fce310280 (&of->mutex){+.+.}, at:
kernfs_fop_write+0x128/0x240
[ÂÂ317.337716]ÂÂ#2: ffff889feb6d4830 (kn->count#115){.+.+}, at:
kernfs_fop_write+0x138/0x240
[ÂÂ317.337720]ÂÂ#3: ffffffffb3762d40 (device_hotplug_lock){+.+.}, at:
lock_device_hotplug_sysfs+0x16/0x50
[ÂÂ317.337723]ÂÂ#4: ffff88981f0dc990 (&dev->mutex){....}, at:
device_offline+0x70/0x110
[ÂÂ317.337726]ÂÂ#5: ffffffffb3315250 (cpu_hotplug_lock.rw_sem){++++}, at:
__offline_pages+0xbf/0xa10
[ÂÂ317.337729]ÂÂ#6: ffffffffb35408b0 (mem_hotplug_lock.rw_sem){++++}, at:
percpu_down_write+0x87/0x2f0
[ÂÂ317.337732]ÂÂ#7: ffff88883fff4318 (&(&zone->lock)->rlock){-.-.}, at:
start_isolate_page_range+0x1f7/0x570
[ÂÂ317.337736] stack backtrace:
[ÂÂ317.337737] CPU: 58 PID: 8738 Comm: test.sh Not tainted 5.3.0-next-20190917+
#9
[ÂÂ317.337738] Hardware name: HPE ProLiant DL560 Gen10/ProLiant DL560 Gen10,
BIOS U34 05/21/2019
[ÂÂ317.337739] Call Trace:
[ÂÂ317.337739]ÂÂdump_stack+0x86/0xca
[ÂÂ317.337740]ÂÂprint_circular_bug.cold.31+0x243/0x26e
[ÂÂ317.337741]ÂÂcheck_noncircular+0x29e/0x2e0
[ÂÂ317.337742]ÂÂ? debug_lockdep_rcu_enabled+0x4b/0x60
[ÂÂ317.337742]ÂÂ? print_circular_bug+0x120/0x120
[ÂÂ317.337743]ÂÂ? is_ftrace_trampoline+0x9/0x20
[ÂÂ317.337744]ÂÂ? kernel_text_address+0x59/0xc0
[ÂÂ317.337744]ÂÂ? __kernel_text_address+0x12/0x40
[ÂÂ317.337745]ÂÂcheck_prev_add+0x107/0xea0
[ÂÂ317.337746]ÂÂvalidate_chain+0x8fc/0x1200
[ÂÂ317.337746]ÂÂ? check_prev_add+0xea0/0xea0
[ÂÂ317.337747]ÂÂ? format_decode+0xd6/0x600
[ÂÂ317.337748]ÂÂ? file_dentry_name+0xe0/0xe0
[ÂÂ317.337749]ÂÂ__lock_acquire+0x5b3/0xb40
[ÂÂ317.337749]ÂÂlock_acquire+0x126/0x280
[ÂÂ317.337750]ÂÂ? down_trylock+0x16/0x50
[ÂÂ317.337751]ÂÂ? vprintk_emit+0x100/0x340
[ÂÂ317.337752]ÂÂ_raw_spin_lock_irqsave+0x3a/0x50
[ÂÂ317.337753]ÂÂ? down_trylock+0x16/0x50
[ÂÂ317.337753]ÂÂdown_trylock+0x16/0x50
[ÂÂ317.337754]ÂÂ? vprintk_emit+0x100/0x340
[ÂÂ317.337755]ÂÂ__down_trylock_console_sem+0x2b/0xa0
[ÂÂ317.337756]ÂÂconsole_trylock+0x16/0x60
[ÂÂ317.337756]ÂÂvprintk_emit+0x100/0x340
[ÂÂ317.337757]ÂÂvprintk_default+0x1f/0x30
[ÂÂ317.337758]ÂÂvprintk_func+0x44/0xd4
[ÂÂ317.337758]ÂÂprintk+0x9f/0xc5
[ÂÂ317.337759]ÂÂ? kmsg_dump_rewind_nolock+0x64/0x64
[ÂÂ317.337760]ÂÂ? __dump_page+0x1d7/0x430
[ÂÂ317.337760]ÂÂ__dump_page.cold.2+0x73/0x210
[ÂÂ317.337761]ÂÂdump_page+0x12/0x50
[ÂÂ317.337762]ÂÂhas_unmovable_pages+0x3e9/0x4b0
[ÂÂ317.337763]ÂÂstart_isolate_page_range+0x3b4/0x570
[ÂÂ317.337763]ÂÂ? unset_migratetype_isolate+0x280/0x280
[ÂÂ317.337764]ÂÂ? rcu_read_lock_bh_held+0xc0/0xc0
[ÂÂ317.337765]ÂÂ__offline_pages+0x1ad/0xa10
[ÂÂ317.337765]ÂÂ? lock_acquire+0x126/0x280
[ÂÂ317.337766]ÂÂ? __add_memory+0xc0/0xc0
[ÂÂ317.337767]ÂÂ? __kasan_check_write+0x14/0x20
[ÂÂ317.337767]ÂÂ? __mutex_lock+0x344/0xcd0
[ÂÂ317.337768]ÂÂ? _raw_spin_unlock_irqrestore+0x49/0x50
[ÂÂ317.337769]ÂÂ? device_offline+0x70/0x110
[ÂÂ317.337770]ÂÂ? klist_next+0x1c1/0x1e0
[ÂÂ317.337770]ÂÂ? __mutex_add_waiter+0xc0/0xc0
[ÂÂ317.337771]ÂÂ? klist_next+0x10b/0x1e0
[ÂÂ317.337772]ÂÂ? klist_iter_exit+0x16/0x40
[ÂÂ317.337772]ÂÂ? device_for_each_child+0xd0/0x110
[ÂÂ317.337773]ÂÂoffline_pages+0x11/0x20
[ÂÂ317.337774]ÂÂmemory_subsys_offline+0x7e/0xc0
[ÂÂ317.337774]ÂÂdevice_offline+0xd5/0x110
[ÂÂ317.337775]ÂÂ? auto_online_blocks_show+0x70/0x70
[ÂÂ317.337776]ÂÂstate_store+0xc6/0xe0
[ÂÂ317.337776]ÂÂdev_attr_store+0x3f/0x60
[ÂÂ317.337777]ÂÂ? device_match_name+0x40/0x40
[ÂÂ317.337778]ÂÂsysfs_kf_write+0x89/0xb0
[ÂÂ317.337778]ÂÂ? sysfs_file_ops+0xa0/0xa0
[ÂÂ317.337779]ÂÂkernfs_fop_write+0x188/0x240
[ÂÂ317.337780]ÂÂ__vfs_write+0x50/0xa0
[ÂÂ317.337780]ÂÂvfs_write+0x105/0x290
[ÂÂ317.337781]ÂÂksys_write+0xc6/0x160
[ÂÂ317.337782]ÂÂ? __x64_sys_read+0x50/0x50
[ÂÂ317.337782]ÂÂ? do_syscall_64+0x79/0x76c
[ÂÂ317.337783]ÂÂ? do_syscall_64+0x79/0x76c
[ÂÂ317.337784]ÂÂ__x64_sys_write+0x43/0x50
[ÂÂ317.337784]ÂÂdo_syscall_64+0xcc/0x76c
[ÂÂ317.337785]ÂÂ? trace_hardirqs_on_thunk+0x1a/0x20
[ÂÂ317.337786]ÂÂ? syscall_return_slowpath+0x210/0x210
[ÂÂ317.337787]ÂÂ? entry_SYSCALL_64_after_hwframe+0x3e/0xbe
[ÂÂ317.337787]ÂÂ? trace_hardirqs_off_caller+0x3a/0x150
[ÂÂ317.337788]ÂÂ? trace_hardirqs_off_thunk+0x1a/0x20
[ÂÂ317.337789]ÂÂentry_SYSCALL_64_after_hwframe+0x49/0xbe