Linux-mm Archive on lore.kernel.org
 help / color / Atom feed
* page_alloc.shuffle=1 + CONFIG_PROVE_LOCKING=y = arm64 hang
@ 2019-08-22 21:33 Qian Cai
  2019-08-23 11:37 ` Will Deacon
  2019-09-05 21:08 ` Qian Cai
  0 siblings, 2 replies; 16+ messages in thread
From: Qian Cai @ 2019-08-22 21:33 UTC (permalink / raw)
  To: Catalin Marinas, Will Deacon
  Cc: Dan Williams, linux-mm, linux-kernel, linux-arm-kernel, Peter Zijlstra

https://raw.githubusercontent.com/cailca/linux-mm/master/arm64.config

Booting an arm64 ThunderX2 server with page_alloc.shuffle=1 [1] +
CONFIG_PROVE_LOCKING=y results in hanging.

[1] https://lore.kernel.org/linux-mm/154899811208.3165233.17623209031065121886.s
tgit@dwillia2-desk3.amr.corp.intel.com/

...
[  125.142689][    T1] arm-smmu-v3 arm-smmu-v3.2.auto: option mask 0x2
[  125.149687][    T1] arm-smmu-v3 arm-smmu-v3.2.auto: ias 44-bit, oas 44-bit
(features 0x0000170d)
[  125.165198][    T1] arm-smmu-v3 arm-smmu-v3.2.auto: allocated 524288 entries
for cmdq
[  125.239425][ [  125.251484][    T1] arm-smmu-v3 arm-smmu-v3.3.auto: option
mask 0x2
[  125.258233][    T1] arm-smmu-v3 arm-smmu-v3.3.auto: ias 44-bit, oas 44-bit
(features 0x0000170d)
[  125.282750][    T1] arm-smmu-v3 arm-smmu-v3.3.auto: allocated 524288 entries
for cmdq
[  125.320097][    T1] arm-smmu-v3 arm-smmu-v3.3.auto: allocated 524288 entries
for evtq
[  125.332667][    T1] arm-smmu-v3 arm-smmu-v3.4.auto: option mask 0x2
[  125.339427][    T1] arm-smmu-v3 arm-smmu-v3.4.auto: ias 44-bit, oas 44-bit
(features 0x0000170d)
[  125.354846][    T1] arm-smmu-v3 arm-smmu-v3.4.auto: allocated 524288 entries
for cmdq
[  125.375295][    T1] arm-smmu-v3 arm-smmu-v3.4.auto: allocated 524288 entries
for evtq
[  125.387371][    T1] arm-smmu-v3 arm-smmu-v3.5.auto: option mask 0x2
[  125.393955][    T1] arm-smmu-v3 arm-smmu-v3.5.auto: ias 44-bit, oas 44-bit
(features 0x0000170d)
[  125.522605][    T1] arm-smmu-v3 arm-smmu-v3.5.auto: allocated 524288 entries
for cmdq
[  125.543338][    T1] arm-smmu-v3 arm-smmu-v3.5.auto: allocated 524288 entries
for evtq
[  126.694742][    T1] EFI Variables Facility v0.08 2004-May-17
[  126.799291][    T1] NET: Registered protocol family 17
[  126.978632][    T1] zswap: loaded using pool lzo/zbud
[  126.989168][    T1] kmemleak: Kernel memory leak detector initialized
[  126.989191][ T1577] kmemleak: Automatic memory scanning thread started
[  127.044079][ T1335] pcieport 0000:0f:00.0: Adding to iommu group 0
[  127.388074][    T1] Freeing unused kernel memory: 22528K
[  133.527005][    T1] Checked W+X mappings: passed, no W+X pages found
[  133.533474][    T1] Run /init as init process
[  133.727196][    T1] systemd[1]: System time before build time, advancing
clock.
[  134.576021][ T1587] modprobe (1587) used greatest stack depth: 27056 bytes
left
[  134.764026][    T1] systemd[1]: systemd 239 running in system mode. (+PAM
+AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT
+GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-
hierarchy=legacy)
[  134.799044][    T1] systemd[1]: Detected architecture arm64.
[  134.804818][    T1] systemd[1]: Running in initial RAM disk.
<...hang...>

Fix it by either set page_alloc.shuffle=0 or CONFIG_PROVE_LOCKING=n which allow
it to continue successfully.


[  121.093846][    T1] systemd[1]: Set hostname to <hpe-apollo-cn99xx>.
[  123.157524][    T1] random: systemd: uninitialized urandom read (16 bytes
read)
[  123.168562][    T1] systemd[1]: Listening on Journal Socket.
[  OK  ] Listening on Journal Socket.
[  123.203932][    T1] random: systemd: uninitialized urandom read (16 bytes
read)
[  123.212813][    T1] systemd[1]: Listening on udev Kernel Socket.
[  OK  ] Listening on udev Kernel Socket.
...


^ permalink raw reply	[flat|nested] 16+ messages in thread

* Re: page_alloc.shuffle=1 + CONFIG_PROVE_LOCKING=y = arm64 hang
  2019-08-22 21:33 page_alloc.shuffle=1 + CONFIG_PROVE_LOCKING=y = arm64 hang Qian Cai
@ 2019-08-23 11:37 ` Will Deacon
  2019-08-23 11:52   ` Qian Cai
  2019-09-05 21:08 ` Qian Cai
  1 sibling, 1 reply; 16+ messages in thread
From: Will Deacon @ 2019-08-23 11:37 UTC (permalink / raw)
  To: Qian Cai
  Cc: Catalin Marinas, Dan Williams, linux-mm, linux-kernel,
	linux-arm-kernel, Peter Zijlstra

On Thu, Aug 22, 2019 at 05:33:23PM -0400, Qian Cai wrote:
> https://raw.githubusercontent.com/cailca/linux-mm/master/arm64.config
> 
> Booting an arm64 ThunderX2 server with page_alloc.shuffle=1 [1] +
> CONFIG_PROVE_LOCKING=y results in hanging.

Hmm, but the config you link to above has:

# CONFIG_PROVE_LOCKING is not set

so I'm confused. Also, which tree is this?

Will


^ permalink raw reply	[flat|nested] 16+ messages in thread

* Re: page_alloc.shuffle=1 + CONFIG_PROVE_LOCKING=y = arm64 hang
  2019-08-23 11:37 ` Will Deacon
@ 2019-08-23 11:52   ` Qian Cai
  0 siblings, 0 replies; 16+ messages in thread
From: Qian Cai @ 2019-08-23 11:52 UTC (permalink / raw)
  To: Will Deacon
  Cc: Catalin Marinas, Dan Williams, linux-mm, linux-kernel,
	linux-arm-kernel, Peter Zijlstra

On Fri, 2019-08-23 at 12:37 +0100, Will Deacon wrote:
> On Thu, Aug 22, 2019 at 05:33:23PM -0400, Qian Cai wrote:
> > https://raw.githubusercontent.com/cailca/linux-mm/master/arm64.config
> > 
> > Booting an arm64 ThunderX2 server with page_alloc.shuffle=1 [1] +
> > CONFIG_PROVE_LOCKING=y results in hanging.
> 
> Hmm, but the config you link to above has:
> 
> # CONFIG_PROVE_LOCKING is not set
> 
> so I'm confused. Also, which tree is this?

I manually turn on CONFIG_PROVE_LOCKING=y on the top of that, and reproduce on
both the mainline and linux-next trees.


^ permalink raw reply	[flat|nested] 16+ messages in thread

* Re: page_alloc.shuffle=1 + CONFIG_PROVE_LOCKING=y = arm64 hang
  2019-08-22 21:33 page_alloc.shuffle=1 + CONFIG_PROVE_LOCKING=y = arm64 hang Qian Cai
  2019-08-23 11:37 ` Will Deacon
@ 2019-09-05 21:08 ` Qian Cai
  2019-09-10 15:22   ` Qian Cai
  1 sibling, 1 reply; 16+ messages in thread
From: Qian Cai @ 2019-09-05 21:08 UTC (permalink / raw)
  To: Catalin Marinas, Will Deacon
  Cc: Dan Williams, linux-mm, linux-kernel, linux-arm-kernel,
	Peter Zijlstra, Waiman Long, Thomas Gleixner

Another data point is if change CONFIG_DEBUG_OBJECTS_TIMERS from =y to =n, it
will also fix it.

On Thu, 2019-08-22 at 17:33 -0400, Qian Cai wrote:
> https://raw.githubusercontent.com/cailca/linux-mm/master/arm64.config
> 
> Booting an arm64 ThunderX2 server with page_alloc.shuffle=1 [1] +
> CONFIG_PROVE_LOCKING=y results in hanging.
> 
> [1] https://lore.kernel.org/linux-mm/154899811208.3165233.17623209031065121886.s
> tgit@dwillia2-desk3.amr.corp.intel.com/
> 
> ...
> [  125.142689][    T1] arm-smmu-v3 arm-smmu-v3.2.auto: option mask 0x2
> [  125.149687][    T1] arm-smmu-v3 arm-smmu-v3.2.auto: ias 44-bit, oas 44-bit
> (features 0x0000170d)
> [  125.165198][    T1] arm-smmu-v3 arm-smmu-v3.2.auto: allocated 524288 entries
> for cmdq
> [  125.239425][ [  125.251484][    T1] arm-smmu-v3 arm-smmu-v3.3.auto: option
> mask 0x2
> [  125.258233][    T1] arm-smmu-v3 arm-smmu-v3.3.auto: ias 44-bit, oas 44-bit
> (features 0x0000170d)
> [  125.282750][    T1] arm-smmu-v3 arm-smmu-v3.3.auto: allocated 524288 entries
> for cmdq
> [  125.320097][    T1] arm-smmu-v3 arm-smmu-v3.3.auto: allocated 524288 entries
> for evtq
> [  125.332667][    T1] arm-smmu-v3 arm-smmu-v3.4.auto: option mask 0x2
> [  125.339427][    T1] arm-smmu-v3 arm-smmu-v3.4.auto: ias 44-bit, oas 44-bit
> (features 0x0000170d)
> [  125.354846][    T1] arm-smmu-v3 arm-smmu-v3.4.auto: allocated 524288 entries
> for cmdq
> [  125.375295][    T1] arm-smmu-v3 arm-smmu-v3.4.auto: allocated 524288 entries
> for evtq
> [  125.387371][    T1] arm-smmu-v3 arm-smmu-v3.5.auto: option mask 0x2
> [  125.393955][    T1] arm-smmu-v3 arm-smmu-v3.5.auto: ias 44-bit, oas 44-bit
> (features 0x0000170d)
> [  125.522605][    T1] arm-smmu-v3 arm-smmu-v3.5.auto: allocated 524288 entries
> for cmdq
> [  125.543338][    T1] arm-smmu-v3 arm-smmu-v3.5.auto: allocated 524288 entries
> for evtq
> [  126.694742][    T1] EFI Variables Facility v0.08 2004-May-17
> [  126.799291][    T1] NET: Registered protocol family 17
> [  126.978632][    T1] zswap: loaded using pool lzo/zbud
> [  126.989168][    T1] kmemleak: Kernel memory leak detector initialized
> [  126.989191][ T1577] kmemleak: Automatic memory scanning thread started
> [  127.044079][ T1335] pcieport 0000:0f:00.0: Adding to iommu group 0
> [  127.388074][    T1] Freeing unused kernel memory: 22528K
> [  133.527005][    T1] Checked W+X mappings: passed, no W+X pages found
> [  133.533474][    T1] Run /init as init process
> [  133.727196][    T1] systemd[1]: System time before build time, advancing
> clock.
> [  134.576021][ T1587] modprobe (1587) used greatest stack depth: 27056 bytes
> left
> [  134.764026][    T1] systemd[1]: systemd 239 running in system mode. (+PAM
> +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT
> +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-
> hierarchy=legacy)
> [  134.799044][    T1] systemd[1]: Detected architecture arm64.
> [  134.804818][    T1] systemd[1]: Running in initial RAM disk.
> <...hang...>
> 
> Fix it by either set page_alloc.shuffle=0 or CONFIG_PROVE_LOCKING=n which allow
> it to continue successfully.
> 
> 
> [  121.093846][    T1] systemd[1]: Set hostname to <hpe-apollo-cn99xx>.
> [  123.157524][    T1] random: systemd: uninitialized urandom read (16 bytes
> read)
> [  123.168562][    T1] systemd[1]: Listening on Journal Socket.
> [  OK  ] Listening on Journal Socket.
> [  123.203932][    T1] random: systemd: uninitialized urandom read (16 bytes
> read)
> [  123.212813][    T1] systemd[1]: Listening on udev Kernel Socket.
> [  OK  ] Listening on udev Kernel Socket.
> ...


^ permalink raw reply	[flat|nested] 16+ messages in thread

* Re: page_alloc.shuffle=1 + CONFIG_PROVE_LOCKING=y = arm64 hang
  2019-09-05 21:08 ` Qian Cai
@ 2019-09-10 15:22   ` Qian Cai
  2019-09-10 19:49     ` Qian Cai
                       ` (2 more replies)
  0 siblings, 3 replies; 16+ messages in thread
From: Qian Cai @ 2019-09-10 15:22 UTC (permalink / raw)
  To: Petr Mladek, Steven Rostedt, Catalin Marinas, Will Deacon
  Cc: Sergey Senozhatsky, Dan Williams, linux-mm, linux-kernel,
	linux-arm-kernel, Peter Zijlstra, Waiman Long, Thomas Gleixner

On Thu, 2019-09-05 at 17:08 -0400, Qian Cai wrote:
> Another data point is if change CONFIG_DEBUG_OBJECTS_TIMERS from =y to =n, it
> will also fix it.
> 
> On Thu, 2019-08-22 at 17:33 -0400, Qian Cai wrote:
> > https://raw.githubusercontent.com/cailca/linux-mm/master/arm64.config
> > 
> > Booting an arm64 ThunderX2 server with page_alloc.shuffle=1 [1] +
> > CONFIG_PROVE_LOCKING=y results in hanging.
> > 
> > [1] https://lore.kernel.org/linux-mm/154899811208.3165233.17623209031065121886.s
> > tgit@dwillia2-desk3.amr.corp.intel.com/
> > 
> > ...
> > [  125.142689][    T1] arm-smmu-v3 arm-smmu-v3.2.auto: option mask 0x2
> > [  125.149687][    T1] arm-smmu-v3 arm-smmu-v3.2.auto: ias 44-bit, oas 44-bit
> > (features 0x0000170d)
> > [  125.165198][    T1] arm-smmu-v3 arm-smmu-v3.2.auto: allocated 524288 entries
> > for cmdq
> > [  125.239425][ [  125.251484][    T1] arm-smmu-v3 arm-smmu-v3.3.auto: option
> > mask 0x2
> > [  125.258233][    T1] arm-smmu-v3 arm-smmu-v3.3.auto: ias 44-bit, oas 44-bit
> > (features 0x0000170d)
> > [  125.282750][    T1] arm-smmu-v3 arm-smmu-v3.3.auto: allocated 524288 entries
> > for cmdq
> > [  125.320097][    T1] arm-smmu-v3 arm-smmu-v3.3.auto: allocated 524288 entries
> > for evtq
> > [  125.332667][    T1] arm-smmu-v3 arm-smmu-v3.4.auto: option mask 0x2
> > [  125.339427][    T1] arm-smmu-v3 arm-smmu-v3.4.auto: ias 44-bit, oas 44-bit
> > (features 0x0000170d)
> > [  125.354846][    T1] arm-smmu-v3 arm-smmu-v3.4.auto: allocated 524288 entries
> > for cmdq
> > [  125.375295][    T1] arm-smmu-v3 arm-smmu-v3.4.auto: allocated 524288 entries
> > for evtq
> > [  125.387371][    T1] arm-smmu-v3 arm-smmu-v3.5.auto: option mask 0x2
> > [  125.393955][    T1] arm-smmu-v3 arm-smmu-v3.5.auto: ias 44-bit, oas 44-bit
> > (features 0x0000170d)
> > [  125.522605][    T1] arm-smmu-v3 arm-smmu-v3.5.auto: allocated 524288 entries
> > for cmdq
> > [  125.543338][    T1] arm-smmu-v3 arm-smmu-v3.5.auto: allocated 524288 entries
> > for evtq
> > [  126.694742][    T1] EFI Variables Facility v0.08 2004-May-17
> > [  126.799291][    T1] NET: Registered protocol family 17
> > [  126.978632][    T1] zswap: loaded using pool lzo/zbud
> > [  126.989168][    T1] kmemleak: Kernel memory leak detector initialized
> > [  126.989191][ T1577] kmemleak: Automatic memory scanning thread started
> > [  127.044079][ T1335] pcieport 0000:0f:00.0: Adding to iommu group 0
> > [  127.388074][    T1] Freeing unused kernel memory: 22528K
> > [  133.527005][    T1] Checked W+X mappings: passed, no W+X pages found
> > [  133.533474][    T1] Run /init as init process
> > [  133.727196][    T1] systemd[1]: System time before build time, advancing
> > clock.
> > [  134.576021][ T1587] modprobe (1587) used greatest stack depth: 27056 bytes
> > left
> > [  134.764026][    T1] systemd[1]: systemd 239 running in system mode. (+PAM
> > +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT
> > +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-
> > hierarchy=legacy)
> > [  134.799044][    T1] systemd[1]: Detected architecture arm64.
> > [  134.804818][    T1] systemd[1]: Running in initial RAM disk.
> > <...hang...>
> > 
> > Fix it by either set page_alloc.shuffle=0 or CONFIG_PROVE_LOCKING=n which allow
> > it to continue successfully.
> > 
> > 
> > [  121.093846][    T1] systemd[1]: Set hostname to <hpe-apollo-cn99xx>.
> > [  123.157524][    T1] random: systemd: uninitialized urandom read (16 bytes
> > read)
> > [  123.168562][    T1] systemd[1]: Listening on Journal Socket.
> > [  OK  ] Listening on Journal Socket.
> > [  123.203932][    T1] random: systemd: uninitialized urandom read (16 bytes
> > read)
> > [  123.212813][    T1] systemd[1]: Listening on udev Kernel Socket.
> > [  OK  ] Listening on udev Kernel Socket.
> > ...

Not sure if the arm64 hang is just an effect of the potential console deadlock
below. The lockdep splat can be reproduced by set,

CONFIG_DEBUG_OBJECTS_TIMER=n (=y will lead to the hang above)
CONFIG_PROVE_LOCKING=y
CONFIG_SLAB_FREELIST_RANDOM=y (with page_alloc.shuffle=1)

while compiling kernels,

[ 1078.214683][T43784] WARNING: possible circular locking dependency detected
[ 1078.221550][T43784] 5.3.0-rc7-next-20190904 #14 Not tainted
[ 1078.227112][T43784] ------------------------------------------------------
[ 1078.233976][T43784] vi/43784 is trying to acquire lock:
[ 1078.239192][T43784] ffff008b7cff9290 (&(&zone->lock)->rlock){-.-.}, at:
rmqueue_bulk.constprop.21+0xb0/0x1218
[ 1078.249111][T43784] 
[ 1078.249111][T43784] but task is already holding lock:
[ 1078.256322][T43784] ffff00938db47d40 (&(&port->lock)->rlock){-.-.}, at:
pty_write+0x78/0x100
[ 1078.264760][T43784] 
[ 1078.264760][T43784] which lock already depends on the new lock.
[ 1078.264760][T43784] 
[ 1078.275008][T43784] 
[ 1078.275008][T43784] the existing dependency chain (in reverse order) is:
[ 1078.283869][T43784] 
[ 1078.283869][T43784] -> #3 (&(&port->lock)->rlock){-.-.}:
[ 1078.291350][T43784]        __lock_acquire+0x5c8/0xbb0
[ 1078.296394][T43784]        lock_acquire+0x154/0x428
[ 1078.301266][T43784]        _raw_spin_lock_irqsave+0x80/0xa0
[ 1078.306831][T43784]        tty_port_tty_get+0x28/0x68
[ 1078.311873][T43784]        tty_port_default_wakeup+0x20/0x40
[ 1078.317523][T43784]        tty_port_tty_wakeup+0x38/0x48
[ 1078.322827][T43784]        uart_write_wakeup+0x2c/0x50
[ 1078.327956][T43784]        pl011_tx_chars+0x240/0x260
[ 1078.332999][T43784]        pl011_start_tx+0x24/0xa8
[ 1078.337868][T43784]        __uart_start+0x90/0xa0
[ 1078.342563][T43784]        uart_write+0x15c/0x2c8
[ 1078.347261][T43784]        do_output_char+0x1c8/0x2b0
[ 1078.352304][T43784]        n_tty_write+0x300/0x668
[ 1078.357087][T43784]        tty_write+0x2e8/0x430
[ 1078.361696][T43784]        redirected_tty_write+0xcc/0xe8
[ 1078.367086][T43784]        do_iter_write+0x228/0x270
[ 1078.372041][T43784]        vfs_writev+0x10c/0x1c8
[ 1078.376735][T43784]        do_writev+0xdc/0x180
[ 1078.381257][T43784]        __arm64_sys_writev+0x50/0x60
[ 1078.386476][T43784]        el0_svc_handler+0x11c/0x1f0
[ 1078.391606][T43784]        el0_svc+0x8/0xc
[ 1078.395691][T43784] 
[ 1078.395691][T43784] -> #2 (&port_lock_key){-.-.}:
[ 1078.402561][T43784]        __lock_acquire+0x5c8/0xbb0
[ 1078.407604][T43784]        lock_acquire+0x154/0x428
[ 1078.412474][T43784]        _raw_spin_lock+0x68/0x88
[ 1078.417343][T43784]        pl011_console_write+0x2ac/0x318
[ 1078.422820][T43784]        console_unlock+0x3c4/0x898
[ 1078.427863][T43784]        vprintk_emit+0x2d4/0x460
[ 1078.432732][T43784]        vprintk_default+0x48/0x58
[ 1078.437688][T43784]        vprintk_func+0x194/0x250
[ 1078.442557][T43784]        printk+0xbc/0xec
[ 1078.446732][T43784]        register_console+0x4a8/0x580
[ 1078.451947][T43784]        uart_add_one_port+0x748/0x878
[ 1078.457250][T43784]        pl011_register_port+0x98/0x128
[ 1078.462639][T43784]        sbsa_uart_probe+0x398/0x480
[ 1078.467772][T43784]        platform_drv_probe+0x70/0x108
[ 1078.473075][T43784]        really_probe+0x15c/0x5d8
[ 1078.477944][T43784]        driver_probe_device+0x94/0x1d0
[ 1078.483335][T43784]        __device_attach_driver+0x11c/0x1a8
[ 1078.489072][T43784]        bus_for_each_drv+0xf8/0x158
[ 1078.494201][T43784]        __device_attach+0x164/0x240
[ 1078.499331][T43784]        device_initial_probe+0x24/0x30
[ 1078.504721][T43784]        bus_probe_device+0xf0/0x100
[ 1078.509850][T43784]        device_add+0x63c/0x960
[ 1078.514546][T43784]        platform_device_add+0x1ac/0x3b8
[ 1078.520023][T43784]        platform_device_register_full+0x1fc/0x290
[ 1078.526373][T43784]        acpi_create_platform_device.part.0+0x264/0x3a8
[ 1078.533152][T43784]        acpi_create_platform_device+0x68/0x80
[ 1078.539150][T43784]        acpi_default_enumeration+0x34/0x78
[ 1078.544887][T43784]        acpi_bus_attach+0x340/0x3b8
[ 1078.550015][T43784]        acpi_bus_attach+0xf8/0x3b8
[ 1078.555057][T43784]        acpi_bus_attach+0xf8/0x3b8
[ 1078.560099][T43784]        acpi_bus_attach+0xf8/0x3b8
[ 1078.565142][T43784]        acpi_bus_scan+0x9c/0x100
[ 1078.570015][T43784]        acpi_scan_init+0x16c/0x320
[ 1078.575058][T43784]        acpi_init+0x330/0x3b8
[ 1078.579666][T43784]        do_one_initcall+0x158/0x7ec
[ 1078.584797][T43784]        kernel_init_freeable+0x9a8/0xa70
[ 1078.590360][T43784]        kernel_init+0x18/0x138
[ 1078.595055][T43784]        ret_from_fork+0x10/0x1c
[ 1078.599835][T43784] 
[ 1078.599835][T43784] -> #1 (console_owner){-...}:
[ 1078.606618][T43784]        __lock_acquire+0x5c8/0xbb0
[ 1078.611661][T43784]        lock_acquire+0x154/0x428
[ 1078.616530][T43784]        console_unlock+0x298/0x898
[ 1078.621573][T43784]        vprintk_emit+0x2d4/0x460
[ 1078.626442][T43784]        vprintk_default+0x48/0x58
[ 1078.631398][T43784]        vprintk_func+0x194/0x250
[ 1078.636267][T43784]        printk+0xbc/0xec
[ 1078.640443][T43784]        _warn_unseeded_randomness+0xb4/0xd0
[ 1078.646267][T43784]        get_random_u64+0x4c/0x100
[ 1078.651224][T43784]        add_to_free_area_random+0x168/0x1a0
[ 1078.657047][T43784]        free_one_page+0x3dc/0xd08
[ 1078.662003][T43784]        __free_pages_ok+0x490/0xd00
[ 1078.667132][T43784]        __free_pages+0xc4/0x118
[ 1078.671914][T43784]        __free_pages_core+0x2e8/0x428
[ 1078.677219][T43784]        memblock_free_pages+0xa4/0xec
[ 1078.682522][T43784]        memblock_free_all+0x264/0x330
[ 1078.687825][T43784]        mem_init+0x90/0x148
[ 1078.692259][T43784]        start_kernel+0x368/0x684
[ 1078.697126][T43784] 
[ 1078.697126][T43784] -> #0 (&(&zone->lock)->rlock){-.-.}:
[ 1078.704604][T43784]        check_prev_add+0x120/0x1138
[ 1078.709733][T43784]        validate_chain+0x888/0x1270
[ 1078.714863][T43784]        __lock_acquire+0x5c8/0xbb0
[ 1078.719906][T43784]        lock_acquire+0x154/0x428
[ 1078.724776][T43784]        _raw_spin_lock+0x68/0x88
[ 1078.729645][T43784]        rmqueue_bulk.constprop.21+0xb0/0x1218
[ 1078.735643][T43784]        get_page_from_freelist+0x898/0x24a0
[ 1078.741467][T43784]        __alloc_pages_nodemask+0x2a8/0x1d08
[ 1078.747291][T43784]        alloc_pages_current+0xb4/0x150
[ 1078.752682][T43784]        allocate_slab+0xab8/0x2350
[ 1078.757725][T43784]        new_slab+0x98/0xc0
[ 1078.762073][T43784]        ___slab_alloc+0x66c/0xa30
[ 1078.767029][T43784]        __slab_alloc+0x68/0xc8
[ 1078.771725][T43784]        __kmalloc+0x3d4/0x658
[ 1078.776333][T43784]        __tty_buffer_request_room+0xd4/0x220
[ 1078.782244][T43784]        tty_insert_flip_string_fixed_flag+0x6c/0x128
[ 1078.788849][T43784]        pty_write+0x98/0x100
[ 1078.793370][T43784]        n_tty_write+0x2a0/0x668
[ 1078.798152][T43784]        tty_write+0x2e8/0x430
[ 1078.802760][T43784]        __vfs_write+0x5c/0xb0
[ 1078.807368][T43784]        vfs_write+0xf0/0x230
[ 1078.811890][T43784]        ksys_write+0xd4/0x180
[ 1078.816498][T43784]        __arm64_sys_write+0x4c/0x60
[ 1078.821627][T43784]        el0_svc_handler+0x11c/0x1f0
[ 1078.826756][T43784]        el0_svc+0x8/0xc
[ 1078.830842][T43784] 
[ 1078.830842][T43784] other info that might help us debug this:
[ 1078.830842][T43784] 
[ 1078.840918][T43784] Chain exists of:
[ 1078.840918][T43784]   &(&zone->lock)->rlock --> &port_lock_key --> &(&port-
>lock)->rlock
[ 1078.840918][T43784] 
[ 1078.854731][T43784]  Possible unsafe locking scenario:
[ 1078.854731][T43784] 
[ 1078.862029][T43784]        CPU0                    CPU1
[ 1078.867243][T43784]        ----                    ----
[ 1078.872457][T43784]   lock(&(&port->lock)->rlock);
[ 1078.877238][T43784]                                lock(&port_lock_key);
[ 1078.883929][T43784]                                lock(&(&port->lock)-
>rlock);
[ 1078.891228][T43784]   lock(&(&zone->lock)->rlock);
[ 1078.896010][T43784] 
[ 1078.896010][T43784]  *** DEADLOCK ***
[ 1078.896010][T43784] 
[ 1078.904004][T43784] 5 locks held by vi/43784:
[ 1078.908351][T43784]  #0: ffff000c36240890 (&tty->ldisc_sem){++++}, at:
ldsem_down_read+0x44/0x50
[ 1078.917133][T43784]  #1: ffff000c36240918 (&tty->atomic_write_lock){+.+.},
at: tty_write_lock+0x24/0x60
[ 1078.926521][T43784]  #2: ffff000c36240aa0 (&o_tty->termios_rwsem/1){++++},
at: n_tty_write+0x108/0x668
[ 1078.935823][T43784]  #3: ffffa0001e0b2360 (&ldata->output_lock){+.+.}, at:
n_tty_write+0x1d0/0x668
[ 1078.944777][T43784]  #4: ffff00938db47d40 (&(&port->lock)->rlock){-.-.}, at:
pty_write+0x78/0x100
[ 1078.953644][T43784] 
[ 1078.953644][T43784] stack backtrace:
[ 1078.959382][T43784] CPU: 97 PID: 43784 Comm: vi Not tainted 5.3.0-rc7-next-
20190904 #14
[ 1078.967376][T43784] Hardware name: HPE Apollo
70             /C01_APACHE_MB         , BIOS L50_5.13_1.11 06/18/2019
[ 1078.977799][T43784] Call trace:
[ 1078.980932][T43784]  dump_backtrace+0x0/0x228
[ 1078.985279][T43784]  show_stack+0x24/0x30
[ 1078.989282][T43784]  dump_stack+0xe8/0x13c
[ 1078.993370][T43784]  print_circular_bug+0x334/0x3d8
[ 1078.998240][T43784]  check_noncircular+0x268/0x310
[ 1079.003022][T43784]  check_prev_add+0x120/0x1138
[ 1079.007631][T43784]  validate_chain+0x888/0x1270
[ 1079.012241][T43784]  __lock_acquire+0x5c8/0xbb0
[ 1079.016763][T43784]  lock_acquire+0x154/0x428
[ 1079.021111][T43784]  _raw_spin_lock+0x68/0x88
[ 1079.025460][T43784]  rmqueue_bulk.constprop.21+0xb0/0x1218
[ 1079.030937][T43784]  get_page_from_freelist+0x898/0x24a0
[ 1079.036240][T43784]  __alloc_pages_nodemask+0x2a8/0x1d08
[ 1079.041542][T43784]  alloc_pages_current+0xb4/0x150
[ 1079.046412][T43784]  allocate_slab+0xab8/0x2350
[ 1079.050934][T43784]  new_slab+0x98/0xc0
[ 1079.054761][T43784]  ___slab_alloc+0x66c/0xa30
[ 1079.059196][T43784]  __slab_alloc+0x68/0xc8
[ 1079.063371][T43784]  __kmalloc+0x3d4/0x658
[ 1079.067458][T43784]  __tty_buffer_request_room+0xd4/0x220
[ 1079.072847][T43784]  tty_insert_flip_string_fixed_flag+0x6c/0x128
[ 1079.078932][T43784]  pty_write+0x98/0x100
[ 1079.082932][T43784]  n_tty_write+0x2a0/0x668
[ 1079.087193][T43784]  tty_write+0x2e8/0x430
[ 1079.091280][T43784]  __vfs_write+0x5c/0xb0
[ 1079.095367][T43784]  vfs_write+0xf0/0x230
[ 1079.099368][T43784]  ksys_write+0xd4/0x180
[ 1079.103455][T43784]  __arm64_sys_write+0x4c/0x60
[ 1079.108064][T43784]  el0_svc_handler+0x11c/0x1f0
[ 1079.112672][T43784]  el0_svc+0x8/0xc


^ permalink raw reply	[flat|nested] 16+ messages in thread

* Re: page_alloc.shuffle=1 + CONFIG_PROVE_LOCKING=y = arm64 hang
  2019-09-10 15:22   ` Qian Cai
@ 2019-09-10 19:49     ` Qian Cai
  2019-09-12  2:28       ` CONFIG_SHUFFLE_PAGE_ALLOCATOR=y lockdep splat (WAS Re: page_alloc.shuffle=1 + CONFIG_PROVE_LOCKING=y = arm64 hang) Qian Cai
  2019-09-10 20:35     ` page_alloc.shuffle=1 + CONFIG_PROVE_LOCKING=y = arm64 hang Qian Cai
  2019-09-11  1:10     ` Sergey Senozhatsky
  2 siblings, 1 reply; 16+ messages in thread
From: Qian Cai @ 2019-09-10 19:49 UTC (permalink / raw)
  To: Petr Mladek, Steven Rostedt, Catalin Marinas, Will Deacon,
	Theodore Ts'o
  Cc: Sergey Senozhatsky, Dan Williams, linux-mm, linux-kernel,
	linux-arm-kernel, Peter Zijlstra, Waiman Long, Thomas Gleixner

On Tue, 2019-09-10 at 11:22 -0400, Qian Cai wrote:
> On Thu, 2019-09-05 at 17:08 -0400, Qian Cai wrote:
> > Another data point is if change CONFIG_DEBUG_OBJECTS_TIMERS from =y to =n, it
> > will also fix it.
> > 
> > On Thu, 2019-08-22 at 17:33 -0400, Qian Cai wrote:
> > > https://raw.githubusercontent.com/cailca/linux-mm/master/arm64.config
> > > 
> > > Booting an arm64 ThunderX2 server with page_alloc.shuffle=1 [1] +
> > > CONFIG_PROVE_LOCKING=y results in hanging.
> > > 
> > > [1] https://lore.kernel.org/linux-mm/154899811208.3165233.17623209031065121886.s
> > > tgit@dwillia2-desk3.amr.corp.intel.com/
> > > 
> > > ...
> > > [  125.142689][    T1] arm-smmu-v3 arm-smmu-v3.2.auto: option mask 0x2
> > > [  125.149687][    T1] arm-smmu-v3 arm-smmu-v3.2.auto: ias 44-bit, oas 44-bit
> > > (features 0x0000170d)
> > > [  125.165198][    T1] arm-smmu-v3 arm-smmu-v3.2.auto: allocated 524288 entries
> > > for cmdq
> > > [  125.239425][ [  125.251484][    T1] arm-smmu-v3 arm-smmu-v3.3.auto: option
> > > mask 0x2
> > > [  125.258233][    T1] arm-smmu-v3 arm-smmu-v3.3.auto: ias 44-bit, oas 44-bit
> > > (features 0x0000170d)
> > > [  125.282750][    T1] arm-smmu-v3 arm-smmu-v3.3.auto: allocated 524288 entries
> > > for cmdq
> > > [  125.320097][    T1] arm-smmu-v3 arm-smmu-v3.3.auto: allocated 524288 entries
> > > for evtq
> > > [  125.332667][    T1] arm-smmu-v3 arm-smmu-v3.4.auto: option mask 0x2
> > > [  125.339427][    T1] arm-smmu-v3 arm-smmu-v3.4.auto: ias 44-bit, oas 44-bit
> > > (features 0x0000170d)
> > > [  125.354846][    T1] arm-smmu-v3 arm-smmu-v3.4.auto: allocated 524288 entries
> > > for cmdq
> > > [  125.375295][    T1] arm-smmu-v3 arm-smmu-v3.4.auto: allocated 524288 entries
> > > for evtq
> > > [  125.387371][    T1] arm-smmu-v3 arm-smmu-v3.5.auto: option mask 0x2
> > > [  125.393955][    T1] arm-smmu-v3 arm-smmu-v3.5.auto: ias 44-bit, oas 44-bit
> > > (features 0x0000170d)
> > > [  125.522605][    T1] arm-smmu-v3 arm-smmu-v3.5.auto: allocated 524288 entries
> > > for cmdq
> > > [  125.543338][    T1] arm-smmu-v3 arm-smmu-v3.5.auto: allocated 524288 entries
> > > for evtq
> > > [  126.694742][    T1] EFI Variables Facility v0.08 2004-May-17
> > > [  126.799291][    T1] NET: Registered protocol family 17
> > > [  126.978632][    T1] zswap: loaded using pool lzo/zbud
> > > [  126.989168][    T1] kmemleak: Kernel memory leak detector initialized
> > > [  126.989191][ T1577] kmemleak: Automatic memory scanning thread started
> > > [  127.044079][ T1335] pcieport 0000:0f:00.0: Adding to iommu group 0
> > > [  127.388074][    T1] Freeing unused kernel memory: 22528K
> > > [  133.527005][    T1] Checked W+X mappings: passed, no W+X pages found
> > > [  133.533474][    T1] Run /init as init process
> > > [  133.727196][    T1] systemd[1]: System time before build time, advancing
> > > clock.
> > > [  134.576021][ T1587] modprobe (1587) used greatest stack depth: 27056 bytes
> > > left
> > > [  134.764026][    T1] systemd[1]: systemd 239 running in system mode. (+PAM
> > > +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT
> > > +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-
> > > hierarchy=legacy)
> > > [  134.799044][    T1] systemd[1]: Detected architecture arm64.
> > > [  134.804818][    T1] systemd[1]: Running in initial RAM disk.
> > > <...hang...>
> > > 
> > > Fix it by either set page_alloc.shuffle=0 or CONFIG_PROVE_LOCKING=n which allow
> > > it to continue successfully.
> > > 
> > > 
> > > [  121.093846][    T1] systemd[1]: Set hostname to <hpe-apollo-cn99xx>.
> > > [  123.157524][    T1] random: systemd: uninitialized urandom read (16 bytes
> > > read)
> > > [  123.168562][    T1] systemd[1]: Listening on Journal Socket.
> > > [  OK  ] Listening on Journal Socket.
> > > [  123.203932][    T1] random: systemd: uninitialized urandom read (16 bytes
> > > read)
> > > [  123.212813][    T1] systemd[1]: Listening on udev Kernel Socket.
> > > [  OK  ] Listening on udev Kernel Socket.
> > > ...
> 
> Not sure if the arm64 hang is just an effect of the potential console deadlock
> below. The lockdep splat can be reproduced by set,
> 
> CONFIG_DEBUG_OBJECTS_TIMER=n (=y will lead to the hang above)
> CONFIG_PROVE_LOCKING=y
> CONFIG_SLAB_FREELIST_RANDOM=y (with page_alloc.shuffle=1)
> 
> while compiling kernels,
> 
> [ 1078.214683][T43784] WARNING: possible circular locking dependency detected
> [ 1078.221550][T43784] 5.3.0-rc7-next-20190904 #14 Not tainted
> [ 1078.227112][T43784] ------------------------------------------------------
> [ 1078.233976][T43784] vi/43784 is trying to acquire lock:
> [ 1078.239192][T43784] ffff008b7cff9290 (&(&zone->lock)->rlock){-.-.}, at:
> rmqueue_bulk.constprop.21+0xb0/0x1218
> [ 1078.249111][T43784] 
> [ 1078.249111][T43784] but task is already holding lock:
> [ 1078.256322][T43784] ffff00938db47d40 (&(&port->lock)->rlock){-.-.}, at:
> pty_write+0x78/0x100
> [ 1078.264760][T43784] 
> [ 1078.264760][T43784] which lock already depends on the new lock.
> [ 1078.264760][T43784] 
> [ 1078.275008][T43784] 
> [ 1078.275008][T43784] the existing dependency chain (in reverse order) is:
> [ 1078.283869][T43784] 
> [ 1078.283869][T43784] -> #3 (&(&port->lock)->rlock){-.-.}:
> [ 1078.291350][T43784]        __lock_acquire+0x5c8/0xbb0
> [ 1078.296394][T43784]        lock_acquire+0x154/0x428
> [ 1078.301266][T43784]        _raw_spin_lock_irqsave+0x80/0xa0
> [ 1078.306831][T43784]        tty_port_tty_get+0x28/0x68
> [ 1078.311873][T43784]        tty_port_default_wakeup+0x20/0x40
> [ 1078.317523][T43784]        tty_port_tty_wakeup+0x38/0x48
> [ 1078.322827][T43784]        uart_write_wakeup+0x2c/0x50
> [ 1078.327956][T43784]        pl011_tx_chars+0x240/0x260
> [ 1078.332999][T43784]        pl011_start_tx+0x24/0xa8
> [ 1078.337868][T43784]        __uart_start+0x90/0xa0
> [ 1078.342563][T43784]        uart_write+0x15c/0x2c8
> [ 1078.347261][T43784]        do_output_char+0x1c8/0x2b0
> [ 1078.352304][T43784]        n_tty_write+0x300/0x668
> [ 1078.357087][T43784]        tty_write+0x2e8/0x430
> [ 1078.361696][T43784]        redirected_tty_write+0xcc/0xe8
> [ 1078.367086][T43784]        do_iter_write+0x228/0x270
> [ 1078.372041][T43784]        vfs_writev+0x10c/0x1c8
> [ 1078.376735][T43784]        do_writev+0xdc/0x180
> [ 1078.381257][T43784]        __arm64_sys_writev+0x50/0x60
> [ 1078.386476][T43784]        el0_svc_handler+0x11c/0x1f0
> [ 1078.391606][T43784]        el0_svc+0x8/0xc
> [ 1078.395691][T43784] 
> [ 1078.395691][T43784] -> #2 (&port_lock_key){-.-.}:
> [ 1078.402561][T43784]        __lock_acquire+0x5c8/0xbb0
> [ 1078.407604][T43784]        lock_acquire+0x154/0x428
> [ 1078.412474][T43784]        _raw_spin_lock+0x68/0x88
> [ 1078.417343][T43784]        pl011_console_write+0x2ac/0x318
> [ 1078.422820][T43784]        console_unlock+0x3c4/0x898
> [ 1078.427863][T43784]        vprintk_emit+0x2d4/0x460
> [ 1078.432732][T43784]        vprintk_default+0x48/0x58
> [ 1078.437688][T43784]        vprintk_func+0x194/0x250
> [ 1078.442557][T43784]        printk+0xbc/0xec
> [ 1078.446732][T43784]        register_console+0x4a8/0x580
> [ 1078.451947][T43784]        uart_add_one_port+0x748/0x878
> [ 1078.457250][T43784]        pl011_register_port+0x98/0x128
> [ 1078.462639][T43784]        sbsa_uart_probe+0x398/0x480
> [ 1078.467772][T43784]        platform_drv_probe+0x70/0x108
> [ 1078.473075][T43784]        really_probe+0x15c/0x5d8
> [ 1078.477944][T43784]        driver_probe_device+0x94/0x1d0
> [ 1078.483335][T43784]        __device_attach_driver+0x11c/0x1a8
> [ 1078.489072][T43784]        bus_for_each_drv+0xf8/0x158
> [ 1078.494201][T43784]        __device_attach+0x164/0x240
> [ 1078.499331][T43784]        device_initial_probe+0x24/0x30
> [ 1078.504721][T43784]        bus_probe_device+0xf0/0x100
> [ 1078.509850][T43784]        device_add+0x63c/0x960
> [ 1078.514546][T43784]        platform_device_add+0x1ac/0x3b8
> [ 1078.520023][T43784]        platform_device_register_full+0x1fc/0x290
> [ 1078.526373][T43784]        acpi_create_platform_device.part.0+0x264/0x3a8
> [ 1078.533152][T43784]        acpi_create_platform_device+0x68/0x80
> [ 1078.539150][T43784]        acpi_default_enumeration+0x34/0x78
> [ 1078.544887][T43784]        acpi_bus_attach+0x340/0x3b8
> [ 1078.550015][T43784]        acpi_bus_attach+0xf8/0x3b8
> [ 1078.555057][T43784]        acpi_bus_attach+0xf8/0x3b8
> [ 1078.560099][T43784]        acpi_bus_attach+0xf8/0x3b8
> [ 1078.565142][T43784]        acpi_bus_scan+0x9c/0x100
> [ 1078.570015][T43784]        acpi_scan_init+0x16c/0x320
> [ 1078.575058][T43784]        acpi_init+0x330/0x3b8
> [ 1078.579666][T43784]        do_one_initcall+0x158/0x7ec
> [ 1078.584797][T43784]        kernel_init_freeable+0x9a8/0xa70
> [ 1078.590360][T43784]        kernel_init+0x18/0x138
> [ 1078.595055][T43784]        ret_from_fork+0x10/0x1c
> [ 1078.599835][T43784] 
> [ 1078.599835][T43784] -> #1 (console_owner){-...}:
> [ 1078.606618][T43784]        __lock_acquire+0x5c8/0xbb0
> [ 1078.611661][T43784]        lock_acquire+0x154/0x428
> [ 1078.616530][T43784]        console_unlock+0x298/0x898
> [ 1078.621573][T43784]        vprintk_emit+0x2d4/0x460
> [ 1078.626442][T43784]        vprintk_default+0x48/0x58
> [ 1078.631398][T43784]        vprintk_func+0x194/0x250
> [ 1078.636267][T43784]        printk+0xbc/0xec
> [ 1078.640443][T43784]        _warn_unseeded_randomness+0xb4/0xd0
> [ 1078.646267][T43784]        get_random_u64+0x4c/0x100
> [ 1078.651224][T43784]        add_to_free_area_random+0x168/0x1a0
> [ 1078.657047][T43784]        free_one_page+0x3dc/0xd08
> [ 1078.662003][T43784]        __free_pages_ok+0x490/0xd00
> [ 1078.667132][T43784]        __free_pages+0xc4/0x118
> [ 1078.671914][T43784]        __free_pages_core+0x2e8/0x428
> [ 1078.677219][T43784]        memblock_free_pages+0xa4/0xec
> [ 1078.682522][T43784]        memblock_free_all+0x264/0x330
> [ 1078.687825][T43784]        mem_init+0x90/0x148
> [ 1078.692259][T43784]        start_kernel+0x368/0x684
> [ 1078.697126][T43784] 
> [ 1078.697126][T43784] -> #0 (&(&zone->lock)->rlock){-.-.}:
> [ 1078.704604][T43784]        check_prev_add+0x120/0x1138
> [ 1078.709733][T43784]        validate_chain+0x888/0x1270
> [ 1078.714863][T43784]        __lock_acquire+0x5c8/0xbb0
> [ 1078.719906][T43784]        lock_acquire+0x154/0x428
> [ 1078.724776][T43784]        _raw_spin_lock+0x68/0x88
> [ 1078.729645][T43784]        rmqueue_bulk.constprop.21+0xb0/0x1218
> [ 1078.735643][T43784]        get_page_from_freelist+0x898/0x24a0
> [ 1078.741467][T43784]        __alloc_pages_nodemask+0x2a8/0x1d08
> [ 1078.747291][T43784]        alloc_pages_current+0xb4/0x150
> [ 1078.752682][T43784]        allocate_slab+0xab8/0x2350
> [ 1078.757725][T43784]        new_slab+0x98/0xc0
> [ 1078.762073][T43784]        ___slab_alloc+0x66c/0xa30
> [ 1078.767029][T43784]        __slab_alloc+0x68/0xc8
> [ 1078.771725][T43784]        __kmalloc+0x3d4/0x658
> [ 1078.776333][T43784]        __tty_buffer_request_room+0xd4/0x220
> [ 1078.782244][T43784]        tty_insert_flip_string_fixed_flag+0x6c/0x128
> [ 1078.788849][T43784]        pty_write+0x98/0x100
> [ 1078.793370][T43784]        n_tty_write+0x2a0/0x668
> [ 1078.798152][T43784]        tty_write+0x2e8/0x430
> [ 1078.802760][T43784]        __vfs_write+0x5c/0xb0
> [ 1078.807368][T43784]        vfs_write+0xf0/0x230
> [ 1078.811890][T43784]        ksys_write+0xd4/0x180
> [ 1078.816498][T43784]        __arm64_sys_write+0x4c/0x60
> [ 1078.821627][T43784]        el0_svc_handler+0x11c/0x1f0
> [ 1078.826756][T43784]        el0_svc+0x8/0xc
> [ 1078.830842][T43784] 
> [ 1078.830842][T43784] other info that might help us debug this:
> [ 1078.830842][T43784] 
> [ 1078.840918][T43784] Chain exists of:
> [ 1078.840918][T43784]   &(&zone->lock)->rlock --> &port_lock_key --> &(&port-
> > lock)->rlock
> 
> [ 1078.840918][T43784] 
> [ 1078.854731][T43784]  Possible unsafe locking scenario:
> [ 1078.854731][T43784] 
> [ 1078.862029][T43784]        CPU0                    CPU1
> [ 1078.867243][T43784]        ----                    ----
> [ 1078.872457][T43784]   lock(&(&port->lock)->rlock);
> [ 1078.877238][T43784]                                lock(&port_lock_key);
> [ 1078.883929][T43784]                                lock(&(&port->lock)-
> > rlock);
> 
> [ 1078.891228][T43784]   lock(&(&zone->lock)->rlock);
> [ 1078.896010][T43784] 
> [ 1078.896010][T43784]  *** DEADLOCK ***
> [ 1078.896010][T43784] 
> [ 1078.904004][T43784] 5 locks held by vi/43784:
> [ 1078.908351][T43784]  #0: ffff000c36240890 (&tty->ldisc_sem){++++}, at:
> ldsem_down_read+0x44/0x50
> [ 1078.917133][T43784]  #1: ffff000c36240918 (&tty->atomic_write_lock){+.+.},
> at: tty_write_lock+0x24/0x60
> [ 1078.926521][T43784]  #2: ffff000c36240aa0 (&o_tty->termios_rwsem/1){++++},
> at: n_tty_write+0x108/0x668
> [ 1078.935823][T43784]  #3: ffffa0001e0b2360 (&ldata->output_lock){+.+.}, at:
> n_tty_write+0x1d0/0x668
> [ 1078.944777][T43784]  #4: ffff00938db47d40 (&(&port->lock)->rlock){-.-.}, at:
> pty_write+0x78/0x100
> [ 1078.953644][T43784] 
> [ 1078.953644][T43784] stack backtrace:
> [ 1078.959382][T43784] CPU: 97 PID: 43784 Comm: vi Not tainted 5.3.0-rc7-next-
> 20190904 #14
> [ 1078.967376][T43784] Hardware name: HPE Apollo
> 70             /C01_APACHE_MB         , BIOS L50_5.13_1.11 06/18/2019
> [ 1078.977799][T43784] Call trace:
> [ 1078.980932][T43784]  dump_backtrace+0x0/0x228
> [ 1078.985279][T43784]  show_stack+0x24/0x30
> [ 1078.989282][T43784]  dump_stack+0xe8/0x13c
> [ 1078.993370][T43784]  print_circular_bug+0x334/0x3d8
> [ 1078.998240][T43784]  check_noncircular+0x268/0x310
> [ 1079.003022][T43784]  check_prev_add+0x120/0x1138
> [ 1079.007631][T43784]  validate_chain+0x888/0x1270
> [ 1079.012241][T43784]  __lock_acquire+0x5c8/0xbb0
> [ 1079.016763][T43784]  lock_acquire+0x154/0x428
> [ 1079.021111][T43784]  _raw_spin_lock+0x68/0x88
> [ 1079.025460][T43784]  rmqueue_bulk.constprop.21+0xb0/0x1218
> [ 1079.030937][T43784]  get_page_from_freelist+0x898/0x24a0
> [ 1079.036240][T43784]  __alloc_pages_nodemask+0x2a8/0x1d08
> [ 1079.041542][T43784]  alloc_pages_current+0xb4/0x150
> [ 1079.046412][T43784]  allocate_slab+0xab8/0x2350
> [ 1079.050934][T43784]  new_slab+0x98/0xc0
> [ 1079.054761][T43784]  ___slab_alloc+0x66c/0xa30
> [ 1079.059196][T43784]  __slab_alloc+0x68/0xc8
> [ 1079.063371][T43784]  __kmalloc+0x3d4/0x658
> [ 1079.067458][T43784]  __tty_buffer_request_room+0xd4/0x220
> [ 1079.072847][T43784]  tty_insert_flip_string_fixed_flag+0x6c/0x128
> [ 1079.078932][T43784]  pty_write+0x98/0x100
> [ 1079.082932][T43784]  n_tty_write+0x2a0/0x668
> [ 1079.087193][T43784]  tty_write+0x2e8/0x430
> [ 1079.091280][T43784]  __vfs_write+0x5c/0xb0
> [ 1079.095367][T43784]  vfs_write+0xf0/0x230
> [ 1079.099368][T43784]  ksys_write+0xd4/0x180
> [ 1079.103455][T43784]  __arm64_sys_write+0x4c/0x60
> [ 1079.108064][T43784]  el0_svc_handler+0x11c/0x1f0
> [ 1079.112672][T43784]  el0_svc+0x8/0xc

Hmm, it feels like that CONFIG_SHUFFLE_PAGE_ALLOCATOR=y introduces some unique
locking patterns that the lockdep does not like via,

allocate_slab
  shuffle_freelist
    get_random_u32

Here is another splat with while compiling/installing a kernel,

[ 1254.443119][    C2] WARNING: possible circular locking dependency detected
[ 1254.450038][    C2] 5.3.0-rc5-next-20190822 #1 Not tainted
[ 1254.455559][    C2] ------------------------------------------------------
[ 1254.462988][    C2] swapper/2/0 is trying to acquire lock:
[ 1254.468509][    C2] ffffffffa2925218 (random_write_wait.lock){..-.}, at:
__wake_up_common_lock+0xc6/0x150
[ 1254.478154][    C2] 
[ 1254.478154][    C2] but task is already holding lock:
[ 1254.485896][    C2] ffff88845373fda0 (batched_entropy_u32.lock){-.-.}, at:
get_random_u32+0x4c/0xe0
[ 1254.495007][    C2] 
[ 1254.495007][    C2] which lock already depends on the new lock.
[ 1254.495007][    C2] 
[ 1254.505331][    C2] 
[ 1254.505331][    C2] the existing dependency chain (in reverse order) is:
[ 1254.514755][    C2] 
[ 1254.514755][    C2] -> #3 (batched_entropy_u32.lock){-.-.}:
[ 1254.522553][    C2]        __lock_acquire+0x5b3/0xb40
[ 1254.527638][    C2]        lock_acquire+0x126/0x280
[ 1254.533016][    C2]        _raw_spin_lock_irqsave+0x3a/0x50
[ 1254.538624][    C2]        get_random_u32+0x4c/0xe0
[ 1254.543539][    C2]        allocate_slab+0x6d6/0x19c0
[ 1254.548625][    C2]        new_slab+0x46/0x70
[ 1254.553010][    C2]        ___slab_alloc+0x58b/0x960
[ 1254.558533][    C2]        __slab_alloc+0x43/0x70
[ 1254.563269][    C2]        kmem_cache_alloc+0x354/0x460
[ 1254.568534][    C2]        fill_pool+0x272/0x4b0
[ 1254.573182][    C2]        __debug_object_init+0x86/0x7a0
[ 1254.578615][    C2]        debug_object_init+0x16/0x20
[ 1254.584256][    C2]        hrtimer_init+0x27/0x1e0
[ 1254.589079][    C2]        init_dl_task_timer+0x20/0x40
[ 1254.594342][    C2]        __sched_fork+0x10b/0x1f0
[ 1254.599253][    C2]        init_idle+0xac/0x520
[ 1254.603816][    C2]        fork_idle+0x18c/0x230
[ 1254.608933][    C2]        idle_threads_init+0xf0/0x187
[ 1254.614193][    C2]        smp_init+0x1d/0x12d
[ 1254.618671][    C2]        kernel_init_freeable+0x37e/0x76e
[ 1254.624282][    C2]        kernel_init+0x11/0x12f
[ 1254.629016][    C2]        ret_from_fork+0x27/0x50
[ 1254.634344][    C2] 
[ 1254.634344][    C2] -> #2 (&rq->lock){-.-.}:
[ 1254.640831][    C2]        __lock_acquire+0x5b3/0xb40
[ 1254.645917][    C2]        lock_acquire+0x126/0x280
[ 1254.650827][    C2]        _raw_spin_lock+0x2f/0x40
[ 1254.655741][    C2]        task_fork_fair+0x43/0x200
[ 1254.661213][    C2]        sched_fork+0x29b/0x420
[ 1254.665949][    C2]        copy_process+0xf12/0x3180
[ 1254.670947][    C2]        _do_fork+0xef/0x950
[ 1254.675422][    C2]        kernel_thread+0xa8/0xe0
[ 1254.680244][    C2]        rest_init+0x28/0x311
[ 1254.685298][    C2]        arch_call_rest_init+0xe/0x1b
[ 1254.690558][    C2]        start_kernel+0x6eb/0x724
[ 1254.695469][    C2]        x86_64_start_reservations+0x24/0x26
[ 1254.701339][    C2]        x86_64_start_kernel+0xf4/0xfb
[ 1254.706689][    C2]        secondary_startup_64+0xb6/0xc0
[ 1254.712601][    C2] 
[ 1254.712601][    C2] -> #1 (&p->pi_lock){-.-.}:
[ 1254.719263][    C2]        __lock_acquire+0x5b3/0xb40
[ 1254.724349][    C2]        lock_acquire+0x126/0x280
[ 1254.729260][    C2]        _raw_spin_lock_irqsave+0x3a/0x50
[ 1254.735317][    C2]        try_to_wake_up+0xad/0x1050
[ 1254.740403][    C2]        default_wake_function+0x2f/0x40
[ 1254.745929][    C2]        pollwake+0x10d/0x160
[ 1254.750491][    C2]        __wake_up_common+0xc4/0x2a0
[ 1254.755663][    C2]        __wake_up_common_lock+0xea/0x150
[ 1254.761756][    C2]        __wake_up+0x13/0x20
[ 1254.766230][    C2]        account.constprop.9+0x217/0x340
[ 1254.771754][    C2]        extract_entropy.constprop.7+0xcf/0x220
[ 1254.777886][    C2]        _xfer_secondary_pool+0x19a/0x3d0
[ 1254.783981][    C2]        push_to_pool+0x3e/0x230
[ 1254.788805][    C2]        process_one_work+0x52a/0xb40
[ 1254.794064][    C2]        worker_thread+0x63/0x5b0
[ 1254.798977][    C2]        kthread+0x1df/0x200
[ 1254.803451][    C2]        ret_from_fork+0x27/0x50
[ 1254.808787][    C2] 
[ 1254.808787][    C2] -> #0 (random_write_wait.lock){..-.}:
[ 1254.816409][    C2]        check_prev_add+0x107/0xea0
[ 1254.821494][    C2]        validate_chain+0x8fc/0x1200
[ 1254.826667][    C2]        __lock_acquire+0x5b3/0xb40
[ 1254.831751][    C2]        lock_acquire+0x126/0x280
[ 1254.837189][    C2]        _raw_spin_lock_irqsave+0x3a/0x50
[ 1254.842797][    C2]        __wake_up_common_lock+0xc6/0x150
[ 1254.848408][    C2]        __wake_up+0x13/0x20
[ 1254.852882][    C2]        account.constprop.9+0x217/0x340
[ 1254.858988][    C2]        extract_entropy.constprop.7+0xcf/0x220
[ 1254.865122][    C2]        crng_reseed+0xa1/0x3f0
[ 1254.869859][    C2]        _extract_crng+0xc3/0xd0
[ 1254.874682][    C2]        crng_reseed+0x21b/0x3f0
[ 1254.879505][    C2]        _extract_crng+0xc3/0xd0
[ 1254.884772][    C2]        extract_crng+0x40/0x60
[ 1254.889507][    C2]        get_random_u32+0xb4/0xe0
[ 1254.894417][    C2]        allocate_slab+0x6d6/0x19c0
[ 1254.899501][    C2]        new_slab+0x46/0x70
[ 1254.903886][    C2]        ___slab_alloc+0x58b/0x960
[ 1254.909377][    C2]        __slab_alloc+0x43/0x70
[ 1254.914112][    C2]        kmem_cache_alloc+0x354/0x460
[ 1254.919375][    C2]        __build_skb+0x23/0x60
[ 1254.924024][    C2]        __netdev_alloc_skb+0x127/0x1e0
[ 1254.929470][    C2]        tg3_poll_work+0x11b2/0x1f70 [tg3]
[ 1254.935654][    C2]        tg3_poll_msix+0x67/0x330 [tg3]
[ 1254.941092][    C2]        net_rx_action+0x24e/0x7e0
[ 1254.946089][    C2]        __do_softirq+0x123/0x767
[ 1254.951000][    C2]        irq_exit+0xd6/0xf0
[ 1254.955385][    C2]        do_IRQ+0xe2/0x1a0
[ 1254.960155][    C2]        ret_from_intr+0x0/0x2a
[ 1254.964896][    C2]        cpuidle_enter_state+0x156/0x8e0
[ 1254.970418][    C2]        cpuidle_enter+0x41/0x70
[ 1254.975242][    C2]        call_cpuidle+0x5e/0x90
[ 1254.979975][    C2]        do_idle+0x333/0x370
[ 1254.984972][    C2]        cpu_startup_entry+0x1d/0x1f
[ 1254.990148][    C2]        start_secondary+0x290/0x330
[ 1254.995319][    C2]        secondary_startup_64+0xb6/0xc0
[ 1255.000750][    C2] 
[ 1255.000750][    C2] other info that might help us debug this:
[ 1255.000750][    C2] 
[ 1255.011424][    C2] Chain exists of:
[ 1255.011424][    C2]   random_write_wait.lock --> &rq->lock -->
batched_entropy_u32.lock
[ 1255.011424][    C2] 
[ 1255.025245][    C2]  Possible unsafe locking scenario:
[ 1255.025245][    C2] 
[ 1255.033012][    C2]        CPU0                    CPU1
[ 1255.038270][    C2]        ----                    ----
[ 1255.043526][    C2]   lock(batched_entropy_u32.lock);
[ 1255.048610][    C2]                                lock(&rq->lock);
[
1255.054918][    C2]                                lock(batched_entropy_u32.loc
k);
[ 1255.063035][    C2]   lock(random_write_wait.lock);
[ 1255.067945][    C2] 
[ 1255.067945][    C2]  *** DEADLOCK ***
[ 1255.067945][    C2] 
[ 1255.076000][    C2] 1 lock held by swapper/2/0:
[ 1255.080558][    C2]  #0: ffff88845373fda0 (batched_entropy_u32.lock){-.-.},
at: get_random_u32+0x4c/0xe0
[ 1255.090547][    C2] 
[ 1255.090547][    C2] stack backtrace:
[ 1255.096333][    C2] CPU: 2 PID: 0 Comm: swapper/2 Not tainted 5.3.0-rc5-next-
20190822 #1
[ 1255.104473][    C2] Hardware name: HPE ProLiant DL385 Gen10/ProLiant DL385
Gen10, BIOS A40 03/09/2018
[ 1255.114276][    C2] Call Trace:
[ 1255.117439][    C2]  <IRQ>
[ 1255.120169][    C2]  dump_stack+0x86/0xca
[ 1255.124205][    C2]  print_circular_bug.cold.32+0x243/0x26e
[ 1255.129816][    C2]  check_noncircular+0x29e/0x2e0
[ 1255.135221][    C2]  ? __bfs+0x238/0x380
[ 1255.139172][    C2]  ? print_circular_bug+0x120/0x120
[ 1255.144259][    C2]  ? find_usage_forwards+0x7d/0xb0
[ 1255.149260][    C2]  check_prev_add+0x107/0xea0
[ 1255.153823][    C2]  validate_chain+0x8fc/0x1200
[ 1255.159007][    C2]  ? check_prev_add+0xea0/0xea0
[ 1255.163743][    C2]  ? check_usage_backwards+0x210/0x210
[ 1255.169091][    C2]  __lock_acquire+0x5b3/0xb40
[ 1255.173655][    C2]  lock_acquire+0x126/0x280
[ 1255.178041][    C2]  ? __wake_up_common_lock+0xc6/0x150
[ 1255.183732][    C2]  _raw_spin_lock_irqsave+0x3a/0x50
[ 1255.188817][    C2]  ? __wake_up_common_lock+0xc6/0x150
[ 1255.194076][    C2]  __wake_up_common_lock+0xc6/0x150
[ 1255.199163][    C2]  ? __wake_up_common+0x2a0/0x2a0
[ 1255.204078][    C2]  ? rcu_read_lock_any_held.part.5+0x20/0x20
[ 1255.210428][    C2]  __wake_up+0x13/0x20
[ 1255.214379][    C2]  account.constprop.9+0x217/0x340
[ 1255.219377][    C2]  extract_entropy.constprop.7+0xcf/0x220
[ 1255.224987][    C2]  ? crng_reseed+0xa1/0x3f0
[ 1255.229375][    C2]  crng_reseed+0xa1/0x3f0
[ 1255.234122][    C2]  ? rcu_read_lock_sched_held+0xac/0xe0
[ 1255.239556][    C2]  ? check_flags.part.16+0x86/0x220
[ 1255.244641][    C2]  ? extract_entropy.constprop.7+0x220/0x220
[ 1255.250511][    C2]  ? __kasan_check_read+0x11/0x20
[ 1255.255422][    C2]  ? validate_chain+0xab/0x1200
[ 1255.260742][    C2]  ? rcu_read_lock_any_held.part.5+0x20/0x20
[ 1255.266616][    C2]  _extract_crng+0xc3/0xd0
[ 1255.270915][    C2]  crng_reseed+0x21b/0x3f0
[ 1255.275215][    C2]  ? extract_entropy.constprop.7+0x220/0x220
[ 1255.281085][    C2]  ? __kasan_check_write+0x14/0x20
[ 1255.286517][    C2]  ? do_raw_spin_lock+0x118/0x1d0
[ 1255.291428][    C2]  ? rwlock_bug.part.0+0x60/0x60
[ 1255.296251][    C2]  _extract_crng+0xc3/0xd0
[ 1255.300550][    C2]  extract_crng+0x40/0x60
[ 1255.304763][    C2]  get_random_u32+0xb4/0xe0
[ 1255.309640][    C2]  allocate_slab+0x6d6/0x19c0
[ 1255.314203][    C2]  new_slab+0x46/0x70
[ 1255.318066][    C2]  ___slab_alloc+0x58b/0x960
[ 1255.322539][    C2]  ? __build_skb+0x23/0x60
[ 1255.326841][    C2]  ? fault_create_debugfs_attr+0x140/0x140
[ 1255.333048][    C2]  ? __build_skb+0x23/0x60
[ 1255.337348][    C2]  __slab_alloc+0x43/0x70
[ 1255.341559][    C2]  ? __slab_alloc+0x43/0x70
[ 1255.345944][    C2]  ? __build_skb+0x23/0x60
[ 1255.350242][    C2]  kmem_cache_alloc+0x354/0x460
[ 1255.354978][    C2]  ? __netdev_alloc_skb+0x1c6/0x1e0
[ 1255.360626][    C2]  ? trace_hardirqs_on+0x3a/0x160
[ 1255.365535][    C2]  __build_skb+0x23/0x60
[ 1255.369660][    C2]  __netdev_alloc_skb+0x127/0x1e0
[ 1255.374576][    C2]  tg3_poll_work+0x11b2/0x1f70 [tg3]
[ 1255.379750][    C2]  ? find_held_lock+0x11b/0x150
[ 1255.385027][    C2]  ? tg3_tx_recover+0xa0/0xa0 [tg3]
[ 1255.390114][    C2]  ? _raw_spin_unlock_irqrestore+0x38/0x50
[ 1255.395809][    C2]  ? __kasan_check_read+0x11/0x20
[ 1255.400718][    C2]  ? validate_chain+0xab/0x1200
[ 1255.405455][    C2]  ? __wake_up_common+0x2a0/0x2a0
[ 1255.410761][    C2]  ? mark_held_locks+0x34/0xb0
[ 1255.415415][    C2]  tg3_poll_msix+0x67/0x330 [tg3]
[ 1255.420327][    C2]  net_rx_action+0x24e/0x7e0
[ 1255.424800][    C2]  ? find_held_lock+0x11b/0x150
[ 1255.429536][    C2]  ? napi_busy_loop+0x600/0x600
[ 1255.434733][    C2]  ? rcu_read_lock_sched_held+0xac/0xe0
[ 1255.440169][    C2]  ? __do_softirq+0xed/0x767
[ 1255.444642][    C2]  ? rcu_read_lock_any_held.part.5+0x20/0x20
[ 1255.450518][    C2]  ? lockdep_hardirqs_on+0x1b0/0x2a0
[ 1255.455693][    C2]  ? irq_exit+0xd6/0xf0
[ 1255.460280][    C2]  __do_softirq+0x123/0x767
[ 1255.464668][    C2]  irq_exit+0xd6/0xf0
[ 1255.468532][    C2]  do_IRQ+0xe2/0x1a0
[ 1255.472308][    C2]  common_interrupt+0xf/0xf
[ 1255.476694][    C2]  </IRQ>
[ 1255.479509][    C2] RIP: 0010:cpuidle_enter_state+0x156/0x8e0
[ 1255.485750][    C2] Code: bf ff 8b 05 a4 27 2d 01 85 c0 0f 8f 1d 04 00 00 31
ff e8 4d ba 92 ff 80 7d d0 00 0f 85 0b 02 00 00 e8 ae c0 a7 ff fb 45 85 ed <0f>
88 2d 02 00 00 4d 63 fd 49 83 ff 09 0f 87 91 06 00 00 4b 8d 04
[ 1255.505335][    C2] RSP: 0018:ffff888206637cf8 EFLAGS: 00000202 ORIG_RAX:
ffffffffffffffc8
[ 1255.514154][    C2] RAX: 0000000000000000 RBX: ffff889f98b44008 RCX:
ffffffffa116e980
[ 1255.522033][    C2] RDX: 0000000000000007 RSI: dffffc0000000000 RDI:
ffff8882066287ec
[ 1255.529913][    C2] RBP: ffff888206637d48 R08: fffffbfff4557aee R09:
0000000000000000
[ 1255.538278][    C2] R10: 0000000000000000 R11: 0000000000000000 R12:
ffffffffa28e8ac0
[ 1255.546158][    C2] R13: 0000000000000002 R14: 0000012412160253 R15:
ffff889f98b4400c
[ 1255.554040][    C2]  ? lockdep_hardirqs_on+0x1b0/0x2a0
[ 1255.559725][    C2]  ? cpuidle_enter_state+0x152/0x8e0
[ 1255.564898][    C2]  cpuidle_enter+0x41/0x70
[ 1255.569196][    C2]  call_cpuidle+0x5e/0x90
[ 1255.573408][    C2]  do_idle+0x333/0x370
[ 1255.577358][    C2]  ? complete+0x51/0x60
[ 1255.581394][    C2]  ? arch_cpu_idle_exit+0x40/0x40
[ 1255.586777][    C2]  ? complete+0x51/0x60
[ 1255.590814][    C2]  cpu_startup_entry+0x1d/0x1f
[ 1255.595461][    C2]  start_secondary+0x290/0x330
[ 1255.600111][    C2]  ? set_cpu_sibling_map+0x18f0/0x18f0
[ 1255.605460][    C2]  secondary_startup_64+0xb6/0xc0


^ permalink raw reply	[flat|nested] 16+ messages in thread

* Re: page_alloc.shuffle=1 + CONFIG_PROVE_LOCKING=y = arm64 hang
  2019-09-10 15:22   ` Qian Cai
  2019-09-10 19:49     ` Qian Cai
@ 2019-09-10 20:35     ` Qian Cai
  2019-09-11  1:10     ` Sergey Senozhatsky
  2 siblings, 0 replies; 16+ messages in thread
From: Qian Cai @ 2019-09-10 20:35 UTC (permalink / raw)
  To: Petr Mladek, Steven Rostedt, Catalin Marinas, Will Deacon
  Cc: Sergey Senozhatsky, Dan Williams, linux-mm, linux-kernel,
	linux-arm-kernel, Peter Zijlstra, Waiman Long, Thomas Gleixner

On Tue, 2019-09-10 at 11:22 -0400, Qian Cai wrote:
> On Thu, 2019-09-05 at 17:08 -0400, Qian Cai wrote:
> > Another data point is if change CONFIG_DEBUG_OBJECTS_TIMERS from =y to =n, it
> > will also fix it.
> > 
> > On Thu, 2019-08-22 at 17:33 -0400, Qian Cai wrote:
> > > https://raw.githubusercontent.com/cailca/linux-mm/master/arm64.config
> > > 
> > > Booting an arm64 ThunderX2 server with page_alloc.shuffle=1 [1] +
> > > CONFIG_PROVE_LOCKING=y results in hanging.
> > > 
> > > [1] https://lore.kernel.org/linux-mm/154899811208.3165233.17623209031065121886.s
> > > tgit@dwillia2-desk3.amr.corp.intel.com/
> > > 
> > > ...
> > > [  125.142689][    T1] arm-smmu-v3 arm-smmu-v3.2.auto: option mask 0x2
> > > [  125.149687][    T1] arm-smmu-v3 arm-smmu-v3.2.auto: ias 44-bit, oas 44-bit
> > > (features 0x0000170d)
> > > [  125.165198][    T1] arm-smmu-v3 arm-smmu-v3.2.auto: allocated 524288 entries
> > > for cmdq
> > > [  125.239425][ [  125.251484][    T1] arm-smmu-v3 arm-smmu-v3.3.auto: option
> > > mask 0x2
> > > [  125.258233][    T1] arm-smmu-v3 arm-smmu-v3.3.auto: ias 44-bit, oas 44-bit
> > > (features 0x0000170d)
> > > [  125.282750][    T1] arm-smmu-v3 arm-smmu-v3.3.auto: allocated 524288 entries
> > > for cmdq
> > > [  125.320097][    T1] arm-smmu-v3 arm-smmu-v3.3.auto: allocated 524288 entries
> > > for evtq
> > > [  125.332667][    T1] arm-smmu-v3 arm-smmu-v3.4.auto: option mask 0x2
> > > [  125.339427][    T1] arm-smmu-v3 arm-smmu-v3.4.auto: ias 44-bit, oas 44-bit
> > > (features 0x0000170d)
> > > [  125.354846][    T1] arm-smmu-v3 arm-smmu-v3.4.auto: allocated 524288 entries
> > > for cmdq
> > > [  125.375295][    T1] arm-smmu-v3 arm-smmu-v3.4.auto: allocated 524288 entries
> > > for evtq
> > > [  125.387371][    T1] arm-smmu-v3 arm-smmu-v3.5.auto: option mask 0x2
> > > [  125.393955][    T1] arm-smmu-v3 arm-smmu-v3.5.auto: ias 44-bit, oas 44-bit
> > > (features 0x0000170d)
> > > [  125.522605][    T1] arm-smmu-v3 arm-smmu-v3.5.auto: allocated 524288 entries
> > > for cmdq
> > > [  125.543338][    T1] arm-smmu-v3 arm-smmu-v3.5.auto: allocated 524288 entries
> > > for evtq
> > > [  126.694742][    T1] EFI Variables Facility v0.08 2004-May-17
> > > [  126.799291][    T1] NET: Registered protocol family 17
> > > [  126.978632][    T1] zswap: loaded using pool lzo/zbud
> > > [  126.989168][    T1] kmemleak: Kernel memory leak detector initialized
> > > [  126.989191][ T1577] kmemleak: Automatic memory scanning thread started
> > > [  127.044079][ T1335] pcieport 0000:0f:00.0: Adding to iommu group 0
> > > [  127.388074][    T1] Freeing unused kernel memory: 22528K
> > > [  133.527005][    T1] Checked W+X mappings: passed, no W+X pages found
> > > [  133.533474][    T1] Run /init as init process
> > > [  133.727196][    T1] systemd[1]: System time before build time, advancing
> > > clock.
> > > [  134.576021][ T1587] modprobe (1587) used greatest stack depth: 27056 bytes
> > > left
> > > [  134.764026][    T1] systemd[1]: systemd 239 running in system mode. (+PAM
> > > +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT
> > > +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-
> > > hierarchy=legacy)
> > > [  134.799044][    T1] systemd[1]: Detected architecture arm64.
> > > [  134.804818][    T1] systemd[1]: Running in initial RAM disk.
> > > <...hang...>
> > > 
> > > Fix it by either set page_alloc.shuffle=0 or CONFIG_PROVE_LOCKING=n which allow
> > > it to continue successfully.
> > > 
> > > 
> > > [  121.093846][    T1] systemd[1]: Set hostname to <hpe-apollo-cn99xx>.
> > > [  123.157524][    T1] random: systemd: uninitialized urandom read (16 bytes
> > > read)
> > > [  123.168562][    T1] systemd[1]: Listening on Journal Socket.
> > > [  OK  ] Listening on Journal Socket.
> > > [  123.203932][    T1] random: systemd: uninitialized urandom read (16 bytes
> > > read)
> > > [  123.212813][    T1] systemd[1]: Listening on udev Kernel Socket.
> > > [  OK  ] Listening on udev Kernel Socket.
> > > ...
> 
> Not sure if the arm64 hang is just an effect of the potential console deadlock
> below. The lockdep splat can be reproduced by set,
> 
> CONFIG_DEBUG_OBJECTS_TIMER=n (=y will lead to the hang above)
> CONFIG_PROVE_LOCKING=y
> CONFIG_SLAB_FREELIST_RANDOM=y (with page_alloc.shuffle=1)
> 
> while compiling kernels,

This is more than likely, as this debug patch alone will fix the hang,

diff --git a/drivers/char/random.c b/drivers/char/random.c
index 9b54cdb301d3..4d5c38035f03 100644
--- a/drivers/char/random.c
+++ b/drivers/char/random.c
@@ -2323,7 +2323,7 @@ u64 get_random_u64(void)
            return ret;
 #endif
 
-       warn_unseeded_randomness(&previous);
+       //warn_unseeded_randomness(&previous);
 
        batch = raw_cpu_ptr(&batched_entropy_u64);
        spin_lock_irqsave(&batch->batch_lock, flags);

which mostly indicates that the additional printk() from this path due to
"page_alloc.shuffle=1" causes a real deadlock,

allocate_slab
  shuffle_freelist
    get_random_u64
      warn_unseeded_randomness
        printk

> 
> [ 1078.214683][T43784] WARNING: possible circular locking dependency detected
> [ 1078.221550][T43784] 5.3.0-rc7-next-20190904 #14 Not tainted
> [ 1078.227112][T43784] ------------------------------------------------------
> [ 1078.233976][T43784] vi/43784 is trying to acquire lock:
> [ 1078.239192][T43784] ffff008b7cff9290 (&(&zone->lock)->rlock){-.-.}, at:
> rmqueue_bulk.constprop.21+0xb0/0x1218
> [ 1078.249111][T43784] 
> [ 1078.249111][T43784] but task is already holding lock:
> [ 1078.256322][T43784] ffff00938db47d40 (&(&port->lock)->rlock){-.-.}, at:
> pty_write+0x78/0x100
> [ 1078.264760][T43784] 
> [ 1078.264760][T43784] which lock already depends on the new lock.
> [ 1078.264760][T43784] 
> [ 1078.275008][T43784] 
> [ 1078.275008][T43784] the existing dependency chain (in reverse order) is:
> [ 1078.283869][T43784] 
> [ 1078.283869][T43784] -> #3 (&(&port->lock)->rlock){-.-.}:
> [ 1078.291350][T43784]        __lock_acquire+0x5c8/0xbb0
> [ 1078.296394][T43784]        lock_acquire+0x154/0x428
> [ 1078.301266][T43784]        _raw_spin_lock_irqsave+0x80/0xa0
> [ 1078.306831][T43784]        tty_port_tty_get+0x28/0x68
> [ 1078.311873][T43784]        tty_port_default_wakeup+0x20/0x40
> [ 1078.317523][T43784]        tty_port_tty_wakeup+0x38/0x48
> [ 1078.322827][T43784]        uart_write_wakeup+0x2c/0x50
> [ 1078.327956][T43784]        pl011_tx_chars+0x240/0x260
> [ 1078.332999][T43784]        pl011_start_tx+0x24/0xa8
> [ 1078.337868][T43784]        __uart_start+0x90/0xa0
> [ 1078.342563][T43784]        uart_write+0x15c/0x2c8
> [ 1078.347261][T43784]        do_output_char+0x1c8/0x2b0
> [ 1078.352304][T43784]        n_tty_write+0x300/0x668
> [ 1078.357087][T43784]        tty_write+0x2e8/0x430
> [ 1078.361696][T43784]        redirected_tty_write+0xcc/0xe8
> [ 1078.367086][T43784]        do_iter_write+0x228/0x270
> [ 1078.372041][T43784]        vfs_writev+0x10c/0x1c8
> [ 1078.376735][T43784]        do_writev+0xdc/0x180
> [ 1078.381257][T43784]        __arm64_sys_writev+0x50/0x60
> [ 1078.386476][T43784]        el0_svc_handler+0x11c/0x1f0
> [ 1078.391606][T43784]        el0_svc+0x8/0xc
> [ 1078.395691][T43784] 
> [ 1078.395691][T43784] -> #2 (&port_lock_key){-.-.}:
> [ 1078.402561][T43784]        __lock_acquire+0x5c8/0xbb0
> [ 1078.407604][T43784]        lock_acquire+0x154/0x428
> [ 1078.412474][T43784]        _raw_spin_lock+0x68/0x88
> [ 1078.417343][T43784]        pl011_console_write+0x2ac/0x318
> [ 1078.422820][T43784]        console_unlock+0x3c4/0x898
> [ 1078.427863][T43784]        vprintk_emit+0x2d4/0x460
> [ 1078.432732][T43784]        vprintk_default+0x48/0x58
> [ 1078.437688][T43784]        vprintk_func+0x194/0x250
> [ 1078.442557][T43784]        printk+0xbc/0xec
> [ 1078.446732][T43784]        register_console+0x4a8/0x580
> [ 1078.451947][T43784]        uart_add_one_port+0x748/0x878
> [ 1078.457250][T43784]        pl011_register_port+0x98/0x128
> [ 1078.462639][T43784]        sbsa_uart_probe+0x398/0x480
> [ 1078.467772][T43784]        platform_drv_probe+0x70/0x108
> [ 1078.473075][T43784]        really_probe+0x15c/0x5d8
> [ 1078.477944][T43784]        driver_probe_device+0x94/0x1d0
> [ 1078.483335][T43784]        __device_attach_driver+0x11c/0x1a8
> [ 1078.489072][T43784]        bus_for_each_drv+0xf8/0x158
> [ 1078.494201][T43784]        __device_attach+0x164/0x240
> [ 1078.499331][T43784]        device_initial_probe+0x24/0x30
> [ 1078.504721][T43784]        bus_probe_device+0xf0/0x100
> [ 1078.509850][T43784]        device_add+0x63c/0x960
> [ 1078.514546][T43784]        platform_device_add+0x1ac/0x3b8
> [ 1078.520023][T43784]        platform_device_register_full+0x1fc/0x290
> [ 1078.526373][T43784]        acpi_create_platform_device.part.0+0x264/0x3a8
> [ 1078.533152][T43784]        acpi_create_platform_device+0x68/0x80
> [ 1078.539150][T43784]        acpi_default_enumeration+0x34/0x78
> [ 1078.544887][T43784]        acpi_bus_attach+0x340/0x3b8
> [ 1078.550015][T43784]        acpi_bus_attach+0xf8/0x3b8
> [ 1078.555057][T43784]        acpi_bus_attach+0xf8/0x3b8
> [ 1078.560099][T43784]        acpi_bus_attach+0xf8/0x3b8
> [ 1078.565142][T43784]        acpi_bus_scan+0x9c/0x100
> [ 1078.570015][T43784]        acpi_scan_init+0x16c/0x320
> [ 1078.575058][T43784]        acpi_init+0x330/0x3b8
> [ 1078.579666][T43784]        do_one_initcall+0x158/0x7ec
> [ 1078.584797][T43784]        kernel_init_freeable+0x9a8/0xa70
> [ 1078.590360][T43784]        kernel_init+0x18/0x138
> [ 1078.595055][T43784]        ret_from_fork+0x10/0x1c
> [ 1078.599835][T43784] 
> [ 1078.599835][T43784] -> #1 (console_owner){-...}:
> [ 1078.606618][T43784]        __lock_acquire+0x5c8/0xbb0
> [ 1078.611661][T43784]        lock_acquire+0x154/0x428
> [ 1078.616530][T43784]        console_unlock+0x298/0x898
> [ 1078.621573][T43784]        vprintk_emit+0x2d4/0x460
> [ 1078.626442][T43784]        vprintk_default+0x48/0x58
> [ 1078.631398][T43784]        vprintk_func+0x194/0x250
> [ 1078.636267][T43784]        printk+0xbc/0xec
> [ 1078.640443][T43784]        _warn_unseeded_randomness+0xb4/0xd0
> [ 1078.646267][T43784]        get_random_u64+0x4c/0x100
> [ 1078.651224][T43784]        add_to_free_area_random+0x168/0x1a0
> [ 1078.657047][T43784]        free_one_page+0x3dc/0xd08
> [ 1078.662003][T43784]        __free_pages_ok+0x490/0xd00
> [ 1078.667132][T43784]        __free_pages+0xc4/0x118
> [ 1078.671914][T43784]        __free_pages_core+0x2e8/0x428
> [ 1078.677219][T43784]        memblock_free_pages+0xa4/0xec
> [ 1078.682522][T43784]        memblock_free_all+0x264/0x330
> [ 1078.687825][T43784]        mem_init+0x90/0x148
> [ 1078.692259][T43784]        start_kernel+0x368/0x684
> [ 1078.697126][T43784] 
> [ 1078.697126][T43784] -> #0 (&(&zone->lock)->rlock){-.-.}:
> [ 1078.704604][T43784]        check_prev_add+0x120/0x1138
> [ 1078.709733][T43784]        validate_chain+0x888/0x1270
> [ 1078.714863][T43784]        __lock_acquire+0x5c8/0xbb0
> [ 1078.719906][T43784]        lock_acquire+0x154/0x428
> [ 1078.724776][T43784]        _raw_spin_lock+0x68/0x88
> [ 1078.729645][T43784]        rmqueue_bulk.constprop.21+0xb0/0x1218
> [ 1078.735643][T43784]        get_page_from_freelist+0x898/0x24a0
> [ 1078.741467][T43784]        __alloc_pages_nodemask+0x2a8/0x1d08
> [ 1078.747291][T43784]        alloc_pages_current+0xb4/0x150
> [ 1078.752682][T43784]        allocate_slab+0xab8/0x2350
> [ 1078.757725][T43784]        new_slab+0x98/0xc0
> [ 1078.762073][T43784]        ___slab_alloc+0x66c/0xa30
> [ 1078.767029][T43784]        __slab_alloc+0x68/0xc8
> [ 1078.771725][T43784]        __kmalloc+0x3d4/0x658
> [ 1078.776333][T43784]        __tty_buffer_request_room+0xd4/0x220
> [ 1078.782244][T43784]        tty_insert_flip_string_fixed_flag+0x6c/0x128
> [ 1078.788849][T43784]        pty_write+0x98/0x100
> [ 1078.793370][T43784]        n_tty_write+0x2a0/0x668
> [ 1078.798152][T43784]        tty_write+0x2e8/0x430
> [ 1078.802760][T43784]        __vfs_write+0x5c/0xb0
> [ 1078.807368][T43784]        vfs_write+0xf0/0x230
> [ 1078.811890][T43784]        ksys_write+0xd4/0x180
> [ 1078.816498][T43784]        __arm64_sys_write+0x4c/0x60
> [ 1078.821627][T43784]        el0_svc_handler+0x11c/0x1f0
> [ 1078.826756][T43784]        el0_svc+0x8/0xc
> [ 1078.830842][T43784] 
> [ 1078.830842][T43784] other info that might help us debug this:
> [ 1078.830842][T43784] 
> [ 1078.840918][T43784] Chain exists of:
> [ 1078.840918][T43784]   &(&zone->lock)->rlock --> &port_lock_key --> &(&port-
> > lock)->rlock
> 
> [ 1078.840918][T43784] 
> [ 1078.854731][T43784]  Possible unsafe locking scenario:
> [ 1078.854731][T43784] 
> [ 1078.862029][T43784]        CPU0                    CPU1
> [ 1078.867243][T43784]        ----                    ----
> [ 1078.872457][T43784]   lock(&(&port->lock)->rlock);
> [ 1078.877238][T43784]                                lock(&port_lock_key);
> [ 1078.883929][T43784]                                lock(&(&port->lock)-
> > rlock);
> 
> [ 1078.891228][T43784]   lock(&(&zone->lock)->rlock);
> [ 1078.896010][T43784] 
> [ 1078.896010][T43784]  *** DEADLOCK ***
> [ 1078.896010][T43784] 
> [ 1078.904004][T43784] 5 locks held by vi/43784:
> [ 1078.908351][T43784]  #0: ffff000c36240890 (&tty->ldisc_sem){++++}, at:
> ldsem_down_read+0x44/0x50
> [ 1078.917133][T43784]  #1: ffff000c36240918 (&tty->atomic_write_lock){+.+.},
> at: tty_write_lock+0x24/0x60
> [ 1078.926521][T43784]  #2: ffff000c36240aa0 (&o_tty->termios_rwsem/1){++++},
> at: n_tty_write+0x108/0x668
> [ 1078.935823][T43784]  #3: ffffa0001e0b2360 (&ldata->output_lock){+.+.}, at:
> n_tty_write+0x1d0/0x668
> [ 1078.944777][T43784]  #4: ffff00938db47d40 (&(&port->lock)->rlock){-.-.}, at:
> pty_write+0x78/0x100
> [ 1078.953644][T43784] 
> [ 1078.953644][T43784] stack backtrace:
> [ 1078.959382][T43784] CPU: 97 PID: 43784 Comm: vi Not tainted 5.3.0-rc7-next-
> 20190904 #14
> [ 1078.967376][T43784] Hardware name: HPE Apollo
> 70             /C01_APACHE_MB         , BIOS L50_5.13_1.11 06/18/2019
> [ 1078.977799][T43784] Call trace:
> [ 1078.980932][T43784]  dump_backtrace+0x0/0x228
> [ 1078.985279][T43784]  show_stack+0x24/0x30
> [ 1078.989282][T43784]  dump_stack+0xe8/0x13c
> [ 1078.993370][T43784]  print_circular_bug+0x334/0x3d8
> [ 1078.998240][T43784]  check_noncircular+0x268/0x310
> [ 1079.003022][T43784]  check_prev_add+0x120/0x1138
> [ 1079.007631][T43784]  validate_chain+0x888/0x1270
> [ 1079.012241][T43784]  __lock_acquire+0x5c8/0xbb0
> [ 1079.016763][T43784]  lock_acquire+0x154/0x428
> [ 1079.021111][T43784]  _raw_spin_lock+0x68/0x88
> [ 1079.025460][T43784]  rmqueue_bulk.constprop.21+0xb0/0x1218
> [ 1079.030937][T43784]  get_page_from_freelist+0x898/0x24a0
> [ 1079.036240][T43784]  __alloc_pages_nodemask+0x2a8/0x1d08
> [ 1079.041542][T43784]  alloc_pages_current+0xb4/0x150
> [ 1079.046412][T43784]  allocate_slab+0xab8/0x2350
> [ 1079.050934][T43784]  new_slab+0x98/0xc0
> [ 1079.054761][T43784]  ___slab_alloc+0x66c/0xa30
> [ 1079.059196][T43784]  __slab_alloc+0x68/0xc8
> [ 1079.063371][T43784]  __kmalloc+0x3d4/0x658
> [ 1079.067458][T43784]  __tty_buffer_request_room+0xd4/0x220
> [ 1079.072847][T43784]  tty_insert_flip_string_fixed_flag+0x6c/0x128
> [ 1079.078932][T43784]  pty_write+0x98/0x100
> [ 1079.082932][T43784]  n_tty_write+0x2a0/0x668
> [ 1079.087193][T43784]  tty_write+0x2e8/0x430
> [ 1079.091280][T43784]  __vfs_write+0x5c/0xb0
> [ 1079.095367][T43784]  vfs_write+0xf0/0x230
> [ 1079.099368][T43784]  ksys_write+0xd4/0x180
> [ 1079.103455][T43784]  __arm64_sys_write+0x4c/0x60
> [ 1079.108064][T43784]  el0_svc_handler+0x11c/0x1f0
> [ 1079.112672][T43784]  el0_svc+0x8/0xc


^ permalink raw reply	[flat|nested] 16+ messages in thread

* Re: page_alloc.shuffle=1 + CONFIG_PROVE_LOCKING=y = arm64 hang
  2019-09-10 15:22   ` Qian Cai
  2019-09-10 19:49     ` Qian Cai
  2019-09-10 20:35     ` page_alloc.shuffle=1 + CONFIG_PROVE_LOCKING=y = arm64 hang Qian Cai
@ 2019-09-11  1:10     ` Sergey Senozhatsky
  2019-09-12 12:05       ` Qian Cai
  2 siblings, 1 reply; 16+ messages in thread
From: Sergey Senozhatsky @ 2019-09-11  1:10 UTC (permalink / raw)
  To: Qian Cai
  Cc: Petr Mladek, Steven Rostedt, Catalin Marinas, Will Deacon,
	Sergey Senozhatsky, Dan Williams, linux-mm, linux-kernel,
	linux-arm-kernel, Peter Zijlstra, Waiman Long, Thomas Gleixner,
	Theodore Ts'o, Arnd Bergmann, Greg Kroah-Hartman

Cc-ing Ted, Arnd, Greg

On (09/10/19 11:22), Qian Cai wrote:
> [ 1078.283869][T43784] -> #3 (&(&port->lock)->rlock){-.-.}:
> [ 1078.291350][T43784]        __lock_acquire+0x5c8/0xbb0
> [ 1078.296394][T43784]        lock_acquire+0x154/0x428
> [ 1078.301266][T43784]        _raw_spin_lock_irqsave+0x80/0xa0
> [ 1078.306831][T43784]        tty_port_tty_get+0x28/0x68
> [ 1078.311873][T43784]        tty_port_default_wakeup+0x20/0x40
> [ 1078.317523][T43784]        tty_port_tty_wakeup+0x38/0x48
> [ 1078.322827][T43784]        uart_write_wakeup+0x2c/0x50
> [ 1078.327956][T43784]        pl011_tx_chars+0x240/0x260
> [ 1078.332999][T43784]        pl011_start_tx+0x24/0xa8
> [ 1078.337868][T43784]        __uart_start+0x90/0xa0
> [ 1078.342563][T43784]        uart_write+0x15c/0x2c8
> [ 1078.347261][T43784]        do_output_char+0x1c8/0x2b0
> [ 1078.352304][T43784]        n_tty_write+0x300/0x668
> [ 1078.357087][T43784]        tty_write+0x2e8/0x430
> [ 1078.361696][T43784]        redirected_tty_write+0xcc/0xe8
> [ 1078.367086][T43784]        do_iter_write+0x228/0x270
> [ 1078.372041][T43784]        vfs_writev+0x10c/0x1c8
> [ 1078.376735][T43784]        do_writev+0xdc/0x180
> [ 1078.381257][T43784]        __arm64_sys_writev+0x50/0x60
> [ 1078.386476][T43784]        el0_svc_handler+0x11c/0x1f0
> [ 1078.391606][T43784]        el0_svc+0x8/0xc
> [ 1078.395691][T43784] 

uart_port->lock  ->  tty_port->lock

This thing along is already a bit suspicious. We re-enter tty
here: tty -> uart -> serial -> tty

And we re-enter tty under uart_port->lock.

> [ 1078.395691][T43784] -> #2 (&port_lock_key){-.-.}:
> [ 1078.402561][T43784]        __lock_acquire+0x5c8/0xbb0
> [ 1078.407604][T43784]        lock_acquire+0x154/0x428
> [ 1078.412474][T43784]        _raw_spin_lock+0x68/0x88
> [ 1078.417343][T43784]        pl011_console_write+0x2ac/0x318
> [ 1078.422820][T43784]        console_unlock+0x3c4/0x898
> [ 1078.427863][T43784]        vprintk_emit+0x2d4/0x460
> [ 1078.432732][T43784]        vprintk_default+0x48/0x58
> [ 1078.437688][T43784]        vprintk_func+0x194/0x250
> [ 1078.442557][T43784]        printk+0xbc/0xec
> [ 1078.446732][T43784]        register_console+0x4a8/0x580
> [ 1078.451947][T43784]        uart_add_one_port+0x748/0x878
> [ 1078.457250][T43784]        pl011_register_port+0x98/0x128
> [ 1078.462639][T43784]        sbsa_uart_probe+0x398/0x480
> [ 1078.467772][T43784]        platform_drv_probe+0x70/0x108
> [ 1078.473075][T43784]        really_probe+0x15c/0x5d8
> [ 1078.477944][T43784]        driver_probe_device+0x94/0x1d0
> [ 1078.483335][T43784]        __device_attach_driver+0x11c/0x1a8
> [ 1078.489072][T43784]        bus_for_each_drv+0xf8/0x158
> [ 1078.494201][T43784]        __device_attach+0x164/0x240
> [ 1078.499331][T43784]        device_initial_probe+0x24/0x30
> [ 1078.504721][T43784]        bus_probe_device+0xf0/0x100
> [ 1078.509850][T43784]        device_add+0x63c/0x960
> [ 1078.514546][T43784]        platform_device_add+0x1ac/0x3b8
> [ 1078.520023][T43784]        platform_device_register_full+0x1fc/0x290
> [ 1078.526373][T43784]        acpi_create_platform_device.part.0+0x264/0x3a8
> [ 1078.533152][T43784]        acpi_create_platform_device+0x68/0x80
> [ 1078.539150][T43784]        acpi_default_enumeration+0x34/0x78
> [ 1078.544887][T43784]        acpi_bus_attach+0x340/0x3b8
> [ 1078.550015][T43784]        acpi_bus_attach+0xf8/0x3b8
> [ 1078.555057][T43784]        acpi_bus_attach+0xf8/0x3b8
> [ 1078.560099][T43784]        acpi_bus_attach+0xf8/0x3b8
> [ 1078.565142][T43784]        acpi_bus_scan+0x9c/0x100
> [ 1078.570015][T43784]        acpi_scan_init+0x16c/0x320
> [ 1078.575058][T43784]        acpi_init+0x330/0x3b8
> [ 1078.579666][T43784]        do_one_initcall+0x158/0x7ec
> [ 1078.584797][T43784]        kernel_init_freeable+0x9a8/0xa70
> [ 1078.590360][T43784]        kernel_init+0x18/0x138
> [ 1078.595055][T43784]        ret_from_fork+0x10/0x1c
>
> [ 1078.599835][T43784] -> #1 (console_owner){-...}:
> [ 1078.606618][T43784]        __lock_acquire+0x5c8/0xbb0
> [ 1078.611661][T43784]        lock_acquire+0x154/0x428
> [ 1078.616530][T43784]        console_unlock+0x298/0x898
> [ 1078.621573][T43784]        vprintk_emit+0x2d4/0x460
> [ 1078.626442][T43784]        vprintk_default+0x48/0x58
> [ 1078.631398][T43784]        vprintk_func+0x194/0x250
> [ 1078.636267][T43784]        printk+0xbc/0xec
> [ 1078.640443][T43784]        _warn_unseeded_randomness+0xb4/0xd0
> [ 1078.646267][T43784]        get_random_u64+0x4c/0x100
> [ 1078.651224][T43784]        add_to_free_area_random+0x168/0x1a0
> [ 1078.657047][T43784]        free_one_page+0x3dc/0xd08
> [ 1078.662003][T43784]        __free_pages_ok+0x490/0xd00
> [ 1078.667132][T43784]        __free_pages+0xc4/0x118
> [ 1078.671914][T43784]        __free_pages_core+0x2e8/0x428
> [ 1078.677219][T43784]        memblock_free_pages+0xa4/0xec
> [ 1078.682522][T43784]        memblock_free_all+0x264/0x330
> [ 1078.687825][T43784]        mem_init+0x90/0x148
> [ 1078.692259][T43784]        start_kernel+0x368/0x684

zone->lock --> uart_port->lock

Some debugging options/warnings/error print outs/etc introduce
deadlock patterns.

This adds zone->lock --> uart_port->lock, which then brings in
uart_port->lock --> tty_port->lock, which in turn brings
tty_port->lock --> zone->lock.

> [ 1078.697126][T43784] -> #0 (&(&zone->lock)->rlock){-.-.}:
> [ 1078.704604][T43784]        check_prev_add+0x120/0x1138
> [ 1078.709733][T43784]        validate_chain+0x888/0x1270
> [ 1078.714863][T43784]        __lock_acquire+0x5c8/0xbb0
> [ 1078.719906][T43784]        lock_acquire+0x154/0x428
> [ 1078.724776][T43784]        _raw_spin_lock+0x68/0x88
> [ 1078.729645][T43784]        rmqueue_bulk.constprop.21+0xb0/0x1218
> [ 1078.735643][T43784]        get_page_from_freelist+0x898/0x24a0
> [ 1078.741467][T43784]        __alloc_pages_nodemask+0x2a8/0x1d08
> [ 1078.747291][T43784]        alloc_pages_current+0xb4/0x150
> [ 1078.752682][T43784]        allocate_slab+0xab8/0x2350
> [ 1078.757725][T43784]        new_slab+0x98/0xc0
> [ 1078.762073][T43784]        ___slab_alloc+0x66c/0xa30
> [ 1078.767029][T43784]        __slab_alloc+0x68/0xc8
> [ 1078.771725][T43784]        __kmalloc+0x3d4/0x658
> [ 1078.776333][T43784]        __tty_buffer_request_room+0xd4/0x220
> [ 1078.782244][T43784]        tty_insert_flip_string_fixed_flag+0x6c/0x128
> [ 1078.788849][T43784]        pty_write+0x98/0x100
> [ 1078.793370][T43784]        n_tty_write+0x2a0/0x668
> [ 1078.798152][T43784]        tty_write+0x2e8/0x430
> [ 1078.802760][T43784]        __vfs_write+0x5c/0xb0
> [ 1078.807368][T43784]        vfs_write+0xf0/0x230
> [ 1078.811890][T43784]        ksys_write+0xd4/0x180
> [ 1078.816498][T43784]        __arm64_sys_write+0x4c/0x60
> [ 1078.821627][T43784]        el0_svc_handler+0x11c/0x1f0
> [ 1078.826756][T43784]        el0_svc+0x8/0xc

tty_port->lock --> zone->lock

> [ 1078.830842][T43784] other info that might help us debug this:
> [ 1078.830842][T43784] 
> [ 1078.840918][T43784] Chain exists of:
> [ 1078.840918][T43784]   &(&zone->lock)->rlock --> &port_lock_key --> &(&port-> >lock)->rlock
> [ 1078.840918][T43784] 
> [ 1078.854731][T43784]  Possible unsafe locking scenario:
> [ 1078.854731][T43784] 
> [ 1078.862029][T43784]        CPU0                    CPU1
> [ 1078.867243][T43784]        ----                    ----
> [ 1078.872457][T43784]   lock(&(&port->lock)->rlock);
> [ 1078.877238][T43784]                                lock(&port_lock_key);
> [ 1078.883929][T43784]                                lock(&(&port->lock)->rlock);
> [ 1078.891228][T43784]   lock(&(&zone->lock)->rlock);
> [ 1078.896010][T43784] 
> [ 1078.896010][T43784]  *** DEADLOCK ***
[..]
> [ 1078.980932][T43784]  dump_backtrace+0x0/0x228
> [ 1078.985279][T43784]  show_stack+0x24/0x30
> [ 1078.989282][T43784]  dump_stack+0xe8/0x13c
> [ 1078.993370][T43784]  print_circular_bug+0x334/0x3d8
> [ 1078.998240][T43784]  check_noncircular+0x268/0x310
> [ 1079.003022][T43784]  check_prev_add+0x120/0x1138
> [ 1079.007631][T43784]  validate_chain+0x888/0x1270
> [ 1079.012241][T43784]  __lock_acquire+0x5c8/0xbb0
> [ 1079.016763][T43784]  lock_acquire+0x154/0x428
> [ 1079.021111][T43784]  _raw_spin_lock+0x68/0x88
> [ 1079.025460][T43784]  rmqueue_bulk.constprop.21+0xb0/0x1218
> [ 1079.030937][T43784]  get_page_from_freelist+0x898/0x24a0
> [ 1079.036240][T43784]  __alloc_pages_nodemask+0x2a8/0x1d08
> [ 1079.041542][T43784]  alloc_pages_current+0xb4/0x150
> [ 1079.046412][T43784]  allocate_slab+0xab8/0x2350
> [ 1079.050934][T43784]  new_slab+0x98/0xc0
> [ 1079.054761][T43784]  ___slab_alloc+0x66c/0xa30
> [ 1079.059196][T43784]  __slab_alloc+0x68/0xc8
> [ 1079.063371][T43784]  __kmalloc+0x3d4/0x658
> [ 1079.067458][T43784]  __tty_buffer_request_room+0xd4/0x220
> [ 1079.072847][T43784]  tty_insert_flip_string_fixed_flag+0x6c/0x128
> [ 1079.078932][T43784]  pty_write+0x98/0x100
> [ 1079.082932][T43784]  n_tty_write+0x2a0/0x668
> [ 1079.087193][T43784]  tty_write+0x2e8/0x430
> [ 1079.091280][T43784]  __vfs_write+0x5c/0xb0
> [ 1079.095367][T43784]  vfs_write+0xf0/0x230
> [ 1079.099368][T43784]  ksys_write+0xd4/0x180
> [ 1079.103455][T43784]  __arm64_sys_write+0x4c/0x60
> [ 1079.108064][T43784]  el0_svc_handler+0x11c/0x1f0
> [ 1079.112672][T43784]  el0_svc+0x8/0xc

tty_port->lock --> zone->lock

For instance, I don't really like the re-entrant tty, at least not
under uart_port->lock. This, maybe, can be one of the solutions.

Another one, a quick and dirty one, (and so many people will blame
me for this) would be to break zone->{printk}->uart chain...

Something like this

---

 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);


^ permalink raw reply	[flat|nested] 16+ messages in thread

* CONFIG_SHUFFLE_PAGE_ALLOCATOR=y lockdep splat (WAS Re: page_alloc.shuffle=1 + CONFIG_PROVE_LOCKING=y = arm64 hang)
  2019-09-10 19:49     ` Qian Cai
@ 2019-09-12  2:28       ` Qian Cai
  0 siblings, 0 replies; 16+ messages in thread
From: Qian Cai @ 2019-09-12  2:28 UTC (permalink / raw)
  To: Will Deacon, Theodore Ts'o, oleg, gkohli
  Cc: Dan Williams, Linux Memory Management List, LKML,
	linux-arm-kernel, Peter Zijlstra, Waiman Long, Thomas Gleixner

Adjusted Cc a bit as this looks like more of the scheduler territory.

> On Sep 10, 2019, at 3:49 PM, Qian Cai <cai@lca.pw> wrote:
> 
> Hmm, it feels like that CONFIG_SHUFFLE_PAGE_ALLOCATOR=y introduces some unique
> locking patterns that the lockdep does not like via,
> 
> allocate_slab
>  shuffle_freelist
>    get_random_u32
> 
> Here is another splat with while compiling/installing a kernel,
> 
> [ 1254.443119][    C2] WARNING: possible circular locking dependency detected
> [ 1254.450038][    C2] 5.3.0-rc5-next-20190822 #1 Not tainted
> [ 1254.455559][    C2] ------------------------------------------------------
> [ 1254.462988][    C2] swapper/2/0 is trying to acquire lock:
> [ 1254.468509][    C2] ffffffffa2925218 (random_write_wait.lock){..-.}, at:
> __wake_up_common_lock+0xc6/0x150
> [ 1254.478154][    C2] 
> [ 1254.478154][    C2] but task is already holding lock:
> [ 1254.485896][    C2] ffff88845373fda0 (batched_entropy_u32.lock){-.-.}, at:
> get_random_u32+0x4c/0xe0
> [ 1254.495007][    C2] 
> [ 1254.495007][    C2] which lock already depends on the new lock.
> [ 1254.495007][    C2] 
> [ 1254.505331][    C2] 
> [ 1254.505331][    C2] the existing dependency chain (in reverse order) is:
> [ 1254.514755][    C2] 
> [ 1254.514755][    C2] -> #3 (batched_entropy_u32.lock){-.-.}:
> [ 1254.522553][    C2]        __lock_acquire+0x5b3/0xb40
> [ 1254.527638][    C2]        lock_acquire+0x126/0x280
> [ 1254.533016][    C2]        _raw_spin_lock_irqsave+0x3a/0x50
> [ 1254.538624][    C2]        get_random_u32+0x4c/0xe0
> [ 1254.543539][    C2]        allocate_slab+0x6d6/0x19c0
> [ 1254.548625][    C2]        new_slab+0x46/0x70
> [ 1254.553010][    C2]        ___slab_alloc+0x58b/0x960
> [ 1254.558533][    C2]        __slab_alloc+0x43/0x70
> [ 1254.563269][    C2]        kmem_cache_alloc+0x354/0x460
> [ 1254.568534][    C2]        fill_pool+0x272/0x4b0
> [ 1254.573182][    C2]        __debug_object_init+0x86/0x7a0
> [ 1254.578615][    C2]        debug_object_init+0x16/0x20
> [ 1254.584256][    C2]        hrtimer_init+0x27/0x1e0
> [ 1254.589079][    C2]        init_dl_task_timer+0x20/0x40
> [ 1254.594342][    C2]        __sched_fork+0x10b/0x1f0
> [ 1254.599253][    C2]        init_idle+0xac/0x520
> [ 1254.603816][    C2]        fork_idle+0x18c/0x230
> [ 1254.608933][    C2]        idle_threads_init+0xf0/0x187
> [ 1254.614193][    C2]        smp_init+0x1d/0x12d
> [ 1254.618671][    C2]        kernel_init_freeable+0x37e/0x76e
> [ 1254.624282][    C2]        kernel_init+0x11/0x12f
> [ 1254.629016][    C2]        ret_from_fork+0x27/0x50
> [ 1254.634344][    C2] 
> [ 1254.634344][    C2] -> #2 (&rq->lock){-.-.}:
> [ 1254.640831][    C2]        __lock_acquire+0x5b3/0xb40
> [ 1254.645917][    C2]        lock_acquire+0x126/0x280
> [ 1254.650827][    C2]        _raw_spin_lock+0x2f/0x40
> [ 1254.655741][    C2]        task_fork_fair+0x43/0x200
> [ 1254.661213][    C2]        sched_fork+0x29b/0x420
> [ 1254.665949][    C2]        copy_process+0xf12/0x3180
> [ 1254.670947][    C2]        _do_fork+0xef/0x950
> [ 1254.675422][    C2]        kernel_thread+0xa8/0xe0
> [ 1254.680244][    C2]        rest_init+0x28/0x311
> [ 1254.685298][    C2]        arch_call_rest_init+0xe/0x1b
> [ 1254.690558][    C2]        start_kernel+0x6eb/0x724
> [ 1254.695469][    C2]        x86_64_start_reservations+0x24/0x26
> [ 1254.701339][    C2]        x86_64_start_kernel+0xf4/0xfb
> [ 1254.706689][    C2]        secondary_startup_64+0xb6/0xc0
> [ 1254.712601][    C2] 
> [ 1254.712601][    C2] -> #1 (&p->pi_lock){-.-.}:
> [ 1254.719263][    C2]        __lock_acquire+0x5b3/0xb40
> [ 1254.724349][    C2]        lock_acquire+0x126/0x280
> [ 1254.729260][    C2]        _raw_spin_lock_irqsave+0x3a/0x50
> [ 1254.735317][    C2]        try_to_wake_up+0xad/0x1050
> [ 1254.740403][    C2]        default_wake_function+0x2f/0x40
> [ 1254.745929][    C2]        pollwake+0x10d/0x160
> [ 1254.750491][    C2]        __wake_up_common+0xc4/0x2a0
> [ 1254.755663][    C2]        __wake_up_common_lock+0xea/0x150
> [ 1254.761756][    C2]        __wake_up+0x13/0x20
> [ 1254.766230][    C2]        account.constprop.9+0x217/0x340
> [ 1254.771754][    C2]        extract_entropy.constprop.7+0xcf/0x220
> [ 1254.777886][    C2]        _xfer_secondary_pool+0x19a/0x3d0
> [ 1254.783981][    C2]        push_to_pool+0x3e/0x230
> [ 1254.788805][    C2]        process_one_work+0x52a/0xb40
> [ 1254.794064][    C2]        worker_thread+0x63/0x5b0
> [ 1254.798977][    C2]        kthread+0x1df/0x200
> [ 1254.803451][    C2]        ret_from_fork+0x27/0x50
> [ 1254.808787][    C2] 
> [ 1254.808787][    C2] -> #0 (random_write_wait.lock){..-.}:
> [ 1254.816409][    C2]        check_prev_add+0x107/0xea0
> [ 1254.821494][    C2]        validate_chain+0x8fc/0x1200
> [ 1254.826667][    C2]        __lock_acquire+0x5b3/0xb40
> [ 1254.831751][    C2]        lock_acquire+0x126/0x280
> [ 1254.837189][    C2]        _raw_spin_lock_irqsave+0x3a/0x50
> [ 1254.842797][    C2]        __wake_up_common_lock+0xc6/0x150
> [ 1254.848408][    C2]        __wake_up+0x13/0x20
> [ 1254.852882][    C2]        account.constprop.9+0x217/0x340
> [ 1254.858988][    C2]        extract_entropy.constprop.7+0xcf/0x220
> [ 1254.865122][    C2]        crng_reseed+0xa1/0x3f0
> [ 1254.869859][    C2]        _extract_crng+0xc3/0xd0
> [ 1254.874682][    C2]        crng_reseed+0x21b/0x3f0
> [ 1254.879505][    C2]        _extract_crng+0xc3/0xd0
> [ 1254.884772][    C2]        extract_crng+0x40/0x60
> [ 1254.889507][    C2]        get_random_u32+0xb4/0xe0
> [ 1254.894417][    C2]        allocate_slab+0x6d6/0x19c0
> [ 1254.899501][    C2]        new_slab+0x46/0x70
> [ 1254.903886][    C2]        ___slab_alloc+0x58b/0x960
> [ 1254.909377][    C2]        __slab_alloc+0x43/0x70
> [ 1254.914112][    C2]        kmem_cache_alloc+0x354/0x460
> [ 1254.919375][    C2]        __build_skb+0x23/0x60
> [ 1254.924024][    C2]        __netdev_alloc_skb+0x127/0x1e0
> [ 1254.929470][    C2]        tg3_poll_work+0x11b2/0x1f70 [tg3]
> [ 1254.935654][    C2]        tg3_poll_msix+0x67/0x330 [tg3]
> [ 1254.941092][    C2]        net_rx_action+0x24e/0x7e0
> [ 1254.946089][    C2]        __do_softirq+0x123/0x767
> [ 1254.951000][    C2]        irq_exit+0xd6/0xf0
> [ 1254.955385][    C2]        do_IRQ+0xe2/0x1a0
> [ 1254.960155][    C2]        ret_from_intr+0x0/0x2a
> [ 1254.964896][    C2]        cpuidle_enter_state+0x156/0x8e0
> [ 1254.970418][    C2]        cpuidle_enter+0x41/0x70
> [ 1254.975242][    C2]        call_cpuidle+0x5e/0x90
> [ 1254.979975][    C2]        do_idle+0x333/0x370
> [ 1254.984972][    C2]        cpu_startup_entry+0x1d/0x1f
> [ 1254.990148][    C2]        start_secondary+0x290/0x330
> [ 1254.995319][    C2]        secondary_startup_64+0xb6/0xc0
> [ 1255.000750][    C2] 
> [ 1255.000750][    C2] other info that might help us debug this:
> [ 1255.000750][    C2] 
> [ 1255.011424][    C2] Chain exists of:
> [ 1255.011424][    C2]   random_write_wait.lock --> &rq->lock -->
> batched_entropy_u32.lock
> [ 1255.011424][    C2] 
> [ 1255.025245][    C2]  Possible unsafe locking scenario:
> [ 1255.025245][    C2] 
> [ 1255.033012][    C2]        CPU0                    CPU1
> [ 1255.038270][    C2]        ----                    ----
> [ 1255.043526][    C2]   lock(batched_entropy_u32.lock);
> [ 1255.048610][    C2]                                lock(&rq->lock);
> [
> 1255.054918][    C2]                                lock(batched_entropy_u32.loc
> k);
> [ 1255.063035][    C2]   lock(random_write_wait.lock);
> [ 1255.067945][    C2] 
> [ 1255.067945][    C2]  *** DEADLOCK ***
> [ 1255.067945][    C2] 
> [ 1255.076000][    C2] 1 lock held by swapper/2/0:
> [ 1255.080558][    C2]  #0: ffff88845373fda0 (batched_entropy_u32.lock){-.-.},
> at: get_random_u32+0x4c/0xe0
> [ 1255.090547][    C2] 
> [ 1255.090547][    C2] stack backtrace:
> [ 1255.096333][    C2] CPU: 2 PID: 0 Comm: swapper/2 Not tainted 5.3.0-rc5-next-
> 20190822 #1
> [ 1255.104473][    C2] Hardware name: HPE ProLiant DL385 Gen10/ProLiant DL385
> Gen10, BIOS A40 03/09/2018
> [ 1255.114276][    C2] Call Trace:
> [ 1255.117439][    C2]  <IRQ>
> [ 1255.120169][    C2]  dump_stack+0x86/0xca
> [ 1255.124205][    C2]  print_circular_bug.cold.32+0x243/0x26e
> [ 1255.129816][    C2]  check_noncircular+0x29e/0x2e0
> [ 1255.135221][    C2]  ? __bfs+0x238/0x380
> [ 1255.139172][    C2]  ? print_circular_bug+0x120/0x120
> [ 1255.144259][    C2]  ? find_usage_forwards+0x7d/0xb0
> [ 1255.149260][    C2]  check_prev_add+0x107/0xea0
> [ 1255.153823][    C2]  validate_chain+0x8fc/0x1200
> [ 1255.159007][    C2]  ? check_prev_add+0xea0/0xea0
> [ 1255.163743][    C2]  ? check_usage_backwards+0x210/0x210
> [ 1255.169091][    C2]  __lock_acquire+0x5b3/0xb40
> [ 1255.173655][    C2]  lock_acquire+0x126/0x280
> [ 1255.178041][    C2]  ? __wake_up_common_lock+0xc6/0x150
> [ 1255.183732][    C2]  _raw_spin_lock_irqsave+0x3a/0x50
> [ 1255.188817][    C2]  ? __wake_up_common_lock+0xc6/0x150
> [ 1255.194076][    C2]  __wake_up_common_lock+0xc6/0x150
> [ 1255.199163][    C2]  ? __wake_up_common+0x2a0/0x2a0
> [ 1255.204078][    C2]  ? rcu_read_lock_any_held.part.5+0x20/0x20
> [ 1255.210428][    C2]  __wake_up+0x13/0x20
> [ 1255.214379][    C2]  account.constprop.9+0x217/0x340
> [ 1255.219377][    C2]  extract_entropy.constprop.7+0xcf/0x220
> [ 1255.224987][    C2]  ? crng_reseed+0xa1/0x3f0
> [ 1255.229375][    C2]  crng_reseed+0xa1/0x3f0
> [ 1255.234122][    C2]  ? rcu_read_lock_sched_held+0xac/0xe0
> [ 1255.239556][    C2]  ? check_flags.part.16+0x86/0x220
> [ 1255.244641][    C2]  ? extract_entropy.constprop.7+0x220/0x220
> [ 1255.250511][    C2]  ? __kasan_check_read+0x11/0x20
> [ 1255.255422][    C2]  ? validate_chain+0xab/0x1200
> [ 1255.260742][    C2]  ? rcu_read_lock_any_held.part.5+0x20/0x20
> [ 1255.266616][    C2]  _extract_crng+0xc3/0xd0
> [ 1255.270915][    C2]  crng_reseed+0x21b/0x3f0
> [ 1255.275215][    C2]  ? extract_entropy.constprop.7+0x220/0x220
> [ 1255.281085][    C2]  ? __kasan_check_write+0x14/0x20
> [ 1255.286517][    C2]  ? do_raw_spin_lock+0x118/0x1d0
> [ 1255.291428][    C2]  ? rwlock_bug.part.0+0x60/0x60
> [ 1255.296251][    C2]  _extract_crng+0xc3/0xd0
> [ 1255.300550][    C2]  extract_crng+0x40/0x60
> [ 1255.304763][    C2]  get_random_u32+0xb4/0xe0
> [ 1255.309640][    C2]  allocate_slab+0x6d6/0x19c0
> [ 1255.314203][    C2]  new_slab+0x46/0x70
> [ 1255.318066][    C2]  ___slab_alloc+0x58b/0x960
> [ 1255.322539][    C2]  ? __build_skb+0x23/0x60
> [ 1255.326841][    C2]  ? fault_create_debugfs_attr+0x140/0x140
> [ 1255.333048][    C2]  ? __build_skb+0x23/0x60
> [ 1255.337348][    C2]  __slab_alloc+0x43/0x70
> [ 1255.341559][    C2]  ? __slab_alloc+0x43/0x70
> [ 1255.345944][    C2]  ? __build_skb+0x23/0x60
> [ 1255.350242][    C2]  kmem_cache_alloc+0x354/0x460
> [ 1255.354978][    C2]  ? __netdev_alloc_skb+0x1c6/0x1e0
> [ 1255.360626][    C2]  ? trace_hardirqs_on+0x3a/0x160
> [ 1255.365535][    C2]  __build_skb+0x23/0x60
> [ 1255.369660][    C2]  __netdev_alloc_skb+0x127/0x1e0
> [ 1255.374576][    C2]  tg3_poll_work+0x11b2/0x1f70 [tg3]
> [ 1255.379750][    C2]  ? find_held_lock+0x11b/0x150
> [ 1255.385027][    C2]  ? tg3_tx_recover+0xa0/0xa0 [tg3]
> [ 1255.390114][    C2]  ? _raw_spin_unlock_irqrestore+0x38/0x50
> [ 1255.395809][    C2]  ? __kasan_check_read+0x11/0x20
> [ 1255.400718][    C2]  ? validate_chain+0xab/0x1200
> [ 1255.405455][    C2]  ? __wake_up_common+0x2a0/0x2a0
> [ 1255.410761][    C2]  ? mark_held_locks+0x34/0xb0
> [ 1255.415415][    C2]  tg3_poll_msix+0x67/0x330 [tg3]
> [ 1255.420327][    C2]  net_rx_action+0x24e/0x7e0
> [ 1255.424800][    C2]  ? find_held_lock+0x11b/0x150
> [ 1255.429536][    C2]  ? napi_busy_loop+0x600/0x600
> [ 1255.434733][    C2]  ? rcu_read_lock_sched_held+0xac/0xe0
> [ 1255.440169][    C2]  ? __do_softirq+0xed/0x767
> [ 1255.444642][    C2]  ? rcu_read_lock_any_held.part.5+0x20/0x20
> [ 1255.450518][    C2]  ? lockdep_hardirqs_on+0x1b0/0x2a0
> [ 1255.455693][    C2]  ? irq_exit+0xd6/0xf0
> [ 1255.460280][    C2]  __do_softirq+0x123/0x767
> [ 1255.464668][    C2]  irq_exit+0xd6/0xf0
> [ 1255.468532][    C2]  do_IRQ+0xe2/0x1a0
> [ 1255.472308][    C2]  common_interrupt+0xf/0xf
> [ 1255.476694][    C2]  </IRQ>
> [ 1255.479509][    C2] RIP: 0010:cpuidle_enter_state+0x156/0x8e0
> [ 1255.485750][    C2] Code: bf ff 8b 05 a4 27 2d 01 85 c0 0f 8f 1d 04 00 00 31
> ff e8 4d ba 92 ff 80 7d d0 00 0f 85 0b 02 00 00 e8 ae c0 a7 ff fb 45 85 ed <0f>
> 88 2d 02 00 00 4d 63 fd 49 83 ff 09 0f 87 91 06 00 00 4b 8d 04
> [ 1255.505335][    C2] RSP: 0018:ffff888206637cf8 EFLAGS: 00000202 ORIG_RAX:
> ffffffffffffffc8
> [ 1255.514154][    C2] RAX: 0000000000000000 RBX: ffff889f98b44008 RCX:
> ffffffffa116e980
> [ 1255.522033][    C2] RDX: 0000000000000007 RSI: dffffc0000000000 RDI:
> ffff8882066287ec
> [ 1255.529913][    C2] RBP: ffff888206637d48 R08: fffffbfff4557aee R09:
> 0000000000000000
> [ 1255.538278][    C2] R10: 0000000000000000 R11: 0000000000000000 R12:
> ffffffffa28e8ac0
> [ 1255.546158][    C2] R13: 0000000000000002 R14: 0000012412160253 R15:
> ffff889f98b4400c
> [ 1255.554040][    C2]  ? lockdep_hardirqs_on+0x1b0/0x2a0
> [ 1255.559725][    C2]  ? cpuidle_enter_state+0x152/0x8e0
> [ 1255.564898][    C2]  cpuidle_enter+0x41/0x70
> [ 1255.569196][    C2]  call_cpuidle+0x5e/0x90
> [ 1255.573408][    C2]  do_idle+0x333/0x370
> [ 1255.577358][    C2]  ? complete+0x51/0x60
> [ 1255.581394][    C2]  ? arch_cpu_idle_exit+0x40/0x40
> [ 1255.586777][    C2]  ? complete+0x51/0x60
> [ 1255.590814][    C2]  cpu_startup_entry+0x1d/0x1f
> [ 1255.595461][    C2]  start_secondary+0x290/0x330
> [ 1255.600111][    C2]  ? set_cpu_sibling_map+0x18f0/0x18f0
> [ 1255.605460][    C2]  secondary_startup_64+0xb6/0xc0

This looks like a false positive. shuffle_freelist() introduced the chain,

batched_entropy_u32.lock -> random_write_wait.lock

but I can’t see how it is possible to get the reversed chain. Imaging something like this,

 __wake_up_common_lock  <— acquired random_write_wait.lock
      __sched_fork <— is that even possible?
           init_dl_task_timer
              debug_object_init
                   allocate_slab
                      shuffle_freelist
                          get_random_u32 <— acquired batched_entropy_u32.lock

^ permalink raw reply	[flat|nested] 16+ messages in thread

* Re: page_alloc.shuffle=1 + CONFIG_PROVE_LOCKING=y = arm64 hang
  2019-09-11  1:10     ` Sergey Senozhatsky
@ 2019-09-12 12:05       ` Qian Cai
  2019-09-16 14:42         ` Steven Rostedt
  0 siblings, 1 reply; 16+ messages in thread
From: Qian Cai @ 2019-09-12 12:05 UTC (permalink / raw)
  To: Sergey Senozhatsky
  Cc: Petr Mladek, Steven Rostedt, Catalin Marinas, Will Deacon,
	Dan Williams, linux-mm, linux-kernel, linux-arm-kernel,
	Peter Zijlstra, Waiman Long, Thomas Gleixner, Theodore Ts'o,
	Arnd Bergmann, Greg Kroah-Hartman

On Wed, 2019-09-11 at 10:10 +0900, Sergey Senozhatsky wrote:
> Cc-ing Ted, Arnd, Greg
> 
> On (09/10/19 11:22), Qian Cai wrote:
> > [ 1078.283869][T43784] -> #3 (&(&port->lock)->rlock){-.-.}:
> > [ 1078.291350][T43784]        __lock_acquire+0x5c8/0xbb0
> > [ 1078.296394][T43784]        lock_acquire+0x154/0x428
> > [ 1078.301266][T43784]        _raw_spin_lock_irqsave+0x80/0xa0
> > [ 1078.306831][T43784]        tty_port_tty_get+0x28/0x68
> > [ 1078.311873][T43784]        tty_port_default_wakeup+0x20/0x40
> > [ 1078.317523][T43784]        tty_port_tty_wakeup+0x38/0x48
> > [ 1078.322827][T43784]        uart_write_wakeup+0x2c/0x50
> > [ 1078.327956][T43784]        pl011_tx_chars+0x240/0x260
> > [ 1078.332999][T43784]        pl011_start_tx+0x24/0xa8
> > [ 1078.337868][T43784]        __uart_start+0x90/0xa0
> > [ 1078.342563][T43784]        uart_write+0x15c/0x2c8
> > [ 1078.347261][T43784]        do_output_char+0x1c8/0x2b0
> > [ 1078.352304][T43784]        n_tty_write+0x300/0x668
> > [ 1078.357087][T43784]        tty_write+0x2e8/0x430
> > [ 1078.361696][T43784]        redirected_tty_write+0xcc/0xe8
> > [ 1078.367086][T43784]        do_iter_write+0x228/0x270
> > [ 1078.372041][T43784]        vfs_writev+0x10c/0x1c8
> > [ 1078.376735][T43784]        do_writev+0xdc/0x180
> > [ 1078.381257][T43784]        __arm64_sys_writev+0x50/0x60
> > [ 1078.386476][T43784]        el0_svc_handler+0x11c/0x1f0
> > [ 1078.391606][T43784]        el0_svc+0x8/0xc
> > [ 1078.395691][T43784] 
> 
> uart_port->lock  ->  tty_port->lock
> 
> This thing along is already a bit suspicious. We re-enter tty
> here: tty -> uart -> serial -> tty
> 
> And we re-enter tty under uart_port->lock.
> 
> > [ 1078.395691][T43784] -> #2 (&port_lock_key){-.-.}:
> > [ 1078.402561][T43784]        __lock_acquire+0x5c8/0xbb0
> > [ 1078.407604][T43784]        lock_acquire+0x154/0x428
> > [ 1078.412474][T43784]        _raw_spin_lock+0x68/0x88
> > [ 1078.417343][T43784]        pl011_console_write+0x2ac/0x318
> > [ 1078.422820][T43784]        console_unlock+0x3c4/0x898
> > [ 1078.427863][T43784]        vprintk_emit+0x2d4/0x460
> > [ 1078.432732][T43784]        vprintk_default+0x48/0x58
> > [ 1078.437688][T43784]        vprintk_func+0x194/0x250
> > [ 1078.442557][T43784]        printk+0xbc/0xec
> > [ 1078.446732][T43784]        register_console+0x4a8/0x580
> > [ 1078.451947][T43784]        uart_add_one_port+0x748/0x878
> > [ 1078.457250][T43784]        pl011_register_port+0x98/0x128
> > [ 1078.462639][T43784]        sbsa_uart_probe+0x398/0x480
> > [ 1078.467772][T43784]        platform_drv_probe+0x70/0x108
> > [ 1078.473075][T43784]        really_probe+0x15c/0x5d8
> > [ 1078.477944][T43784]        driver_probe_device+0x94/0x1d0
> > [ 1078.483335][T43784]        __device_attach_driver+0x11c/0x1a8
> > [ 1078.489072][T43784]        bus_for_each_drv+0xf8/0x158
> > [ 1078.494201][T43784]        __device_attach+0x164/0x240
> > [ 1078.499331][T43784]        device_initial_probe+0x24/0x30
> > [ 1078.504721][T43784]        bus_probe_device+0xf0/0x100
> > [ 1078.509850][T43784]        device_add+0x63c/0x960
> > [ 1078.514546][T43784]        platform_device_add+0x1ac/0x3b8
> > [ 1078.520023][T43784]        platform_device_register_full+0x1fc/0x290
> > [ 1078.526373][T43784]        acpi_create_platform_device.part.0+0x264/0x3a8
> > [ 1078.533152][T43784]        acpi_create_platform_device+0x68/0x80
> > [ 1078.539150][T43784]        acpi_default_enumeration+0x34/0x78
> > [ 1078.544887][T43784]        acpi_bus_attach+0x340/0x3b8
> > [ 1078.550015][T43784]        acpi_bus_attach+0xf8/0x3b8
> > [ 1078.555057][T43784]        acpi_bus_attach+0xf8/0x3b8
> > [ 1078.560099][T43784]        acpi_bus_attach+0xf8/0x3b8
> > [ 1078.565142][T43784]        acpi_bus_scan+0x9c/0x100
> > [ 1078.570015][T43784]        acpi_scan_init+0x16c/0x320
> > [ 1078.575058][T43784]        acpi_init+0x330/0x3b8
> > [ 1078.579666][T43784]        do_one_initcall+0x158/0x7ec
> > [ 1078.584797][T43784]        kernel_init_freeable+0x9a8/0xa70
> > [ 1078.590360][T43784]        kernel_init+0x18/0x138
> > [ 1078.595055][T43784]        ret_from_fork+0x10/0x1c
> > 
> > [ 1078.599835][T43784] -> #1 (console_owner){-...}:
> > [ 1078.606618][T43784]        __lock_acquire+0x5c8/0xbb0
> > [ 1078.611661][T43784]        lock_acquire+0x154/0x428
> > [ 1078.616530][T43784]        console_unlock+0x298/0x898
> > [ 1078.621573][T43784]        vprintk_emit+0x2d4/0x460
> > [ 1078.626442][T43784]        vprintk_default+0x48/0x58
> > [ 1078.631398][T43784]        vprintk_func+0x194/0x250
> > [ 1078.636267][T43784]        printk+0xbc/0xec
> > [ 1078.640443][T43784]        _warn_unseeded_randomness+0xb4/0xd0
> > [ 1078.646267][T43784]        get_random_u64+0x4c/0x100
> > [ 1078.651224][T43784]        add_to_free_area_random+0x168/0x1a0
> > [ 1078.657047][T43784]        free_one_page+0x3dc/0xd08
> > [ 1078.662003][T43784]        __free_pages_ok+0x490/0xd00
> > [ 1078.667132][T43784]        __free_pages+0xc4/0x118
> > [ 1078.671914][T43784]        __free_pages_core+0x2e8/0x428
> > [ 1078.677219][T43784]        memblock_free_pages+0xa4/0xec
> > [ 1078.682522][T43784]        memblock_free_all+0x264/0x330
> > [ 1078.687825][T43784]        mem_init+0x90/0x148
> > [ 1078.692259][T43784]        start_kernel+0x368/0x684
> 
> zone->lock --> uart_port->lock
> 
> Some debugging options/warnings/error print outs/etc introduce
> deadlock patterns.
> 
> This adds zone->lock --> uart_port->lock, which then brings in
> uart_port->lock --> tty_port->lock, which in turn brings
> tty_port->lock --> zone->lock.
> 
> > [ 1078.697126][T43784] -> #0 (&(&zone->lock)->rlock){-.-.}:
> > [ 1078.704604][T43784]        check_prev_add+0x120/0x1138
> > [ 1078.709733][T43784]        validate_chain+0x888/0x1270
> > [ 1078.714863][T43784]        __lock_acquire+0x5c8/0xbb0
> > [ 1078.719906][T43784]        lock_acquire+0x154/0x428
> > [ 1078.724776][T43784]        _raw_spin_lock+0x68/0x88
> > [ 1078.729645][T43784]        rmqueue_bulk.constprop.21+0xb0/0x1218
> > [ 1078.735643][T43784]        get_page_from_freelist+0x898/0x24a0
> > [ 1078.741467][T43784]        __alloc_pages_nodemask+0x2a8/0x1d08
> > [ 1078.747291][T43784]        alloc_pages_current+0xb4/0x150
> > [ 1078.752682][T43784]        allocate_slab+0xab8/0x2350
> > [ 1078.757725][T43784]        new_slab+0x98/0xc0
> > [ 1078.762073][T43784]        ___slab_alloc+0x66c/0xa30
> > [ 1078.767029][T43784]        __slab_alloc+0x68/0xc8
> > [ 1078.771725][T43784]        __kmalloc+0x3d4/0x658
> > [ 1078.776333][T43784]        __tty_buffer_request_room+0xd4/0x220
> > [ 1078.782244][T43784]        tty_insert_flip_string_fixed_flag+0x6c/0x128
> > [ 1078.788849][T43784]        pty_write+0x98/0x100
> > [ 1078.793370][T43784]        n_tty_write+0x2a0/0x668
> > [ 1078.798152][T43784]        tty_write+0x2e8/0x430
> > [ 1078.802760][T43784]        __vfs_write+0x5c/0xb0
> > [ 1078.807368][T43784]        vfs_write+0xf0/0x230
> > [ 1078.811890][T43784]        ksys_write+0xd4/0x180
> > [ 1078.816498][T43784]        __arm64_sys_write+0x4c/0x60
> > [ 1078.821627][T43784]        el0_svc_handler+0x11c/0x1f0
> > [ 1078.826756][T43784]        el0_svc+0x8/0xc
> 
> tty_port->lock --> zone->lock
> 
> > [ 1078.830842][T43784] other info that might help us debug this:
> > [ 1078.830842][T43784] 
> > [ 1078.840918][T43784] Chain exists of:
> > [ 1078.840918][T43784]   &(&zone->lock)->rlock --> &port_lock_key --> &(&port-> >lock)->rlock
> > [ 1078.840918][T43784] 
> > [ 1078.854731][T43784]  Possible unsafe locking scenario:
> > [ 1078.854731][T43784] 
> > [ 1078.862029][T43784]        CPU0                    CPU1
> > [ 1078.867243][T43784]        ----                    ----
> > [ 1078.872457][T43784]   lock(&(&port->lock)->rlock);
> > [ 1078.877238][T43784]                                lock(&port_lock_key);
> > [ 1078.883929][T43784]                                lock(&(&port->lock)->rlock);
> > [ 1078.891228][T43784]   lock(&(&zone->lock)->rlock);
> > [ 1078.896010][T43784] 
> > [ 1078.896010][T43784]  *** DEADLOCK ***
> 
> [..]
> > [ 1078.980932][T43784]  dump_backtrace+0x0/0x228
> > [ 1078.985279][T43784]  show_stack+0x24/0x30
> > [ 1078.989282][T43784]  dump_stack+0xe8/0x13c
> > [ 1078.993370][T43784]  print_circular_bug+0x334/0x3d8
> > [ 1078.998240][T43784]  check_noncircular+0x268/0x310
> > [ 1079.003022][T43784]  check_prev_add+0x120/0x1138
> > [ 1079.007631][T43784]  validate_chain+0x888/0x1270
> > [ 1079.012241][T43784]  __lock_acquire+0x5c8/0xbb0
> > [ 1079.016763][T43784]  lock_acquire+0x154/0x428
> > [ 1079.021111][T43784]  _raw_spin_lock+0x68/0x88
> > [ 1079.025460][T43784]  rmqueue_bulk.constprop.21+0xb0/0x1218
> > [ 1079.030937][T43784]  get_page_from_freelist+0x898/0x24a0
> > [ 1079.036240][T43784]  __alloc_pages_nodemask+0x2a8/0x1d08
> > [ 1079.041542][T43784]  alloc_pages_current+0xb4/0x150
> > [ 1079.046412][T43784]  allocate_slab+0xab8/0x2350
> > [ 1079.050934][T43784]  new_slab+0x98/0xc0
> > [ 1079.054761][T43784]  ___slab_alloc+0x66c/0xa30
> > [ 1079.059196][T43784]  __slab_alloc+0x68/0xc8
> > [ 1079.063371][T43784]  __kmalloc+0x3d4/0x658
> > [ 1079.067458][T43784]  __tty_buffer_request_room+0xd4/0x220
> > [ 1079.072847][T43784]  tty_insert_flip_string_fixed_flag+0x6c/0x128
> > [ 1079.078932][T43784]  pty_write+0x98/0x100
> > [ 1079.082932][T43784]  n_tty_write+0x2a0/0x668
> > [ 1079.087193][T43784]  tty_write+0x2e8/0x430
> > [ 1079.091280][T43784]  __vfs_write+0x5c/0xb0
> > [ 1079.095367][T43784]  vfs_write+0xf0/0x230
> > [ 1079.099368][T43784]  ksys_write+0xd4/0x180
> > [ 1079.103455][T43784]  __arm64_sys_write+0x4c/0x60
> > [ 1079.108064][T43784]  el0_svc_handler+0x11c/0x1f0
> > [ 1079.112672][T43784]  el0_svc+0x8/0xc
> 
> tty_port->lock --> zone->lock
> 
> For instance, I don't really like the re-entrant tty, at least not
> under uart_port->lock. This, maybe, can be one of the solutions.
> 
> Another one, a quick and dirty one, (and so many people will blame
> me for this) would be to break zone->{printk}->uart chain...
> 
> Something like this
> 
> ---
> 
>  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?


^ permalink raw reply	[flat|nested] 16+ messages in thread

* Re: page_alloc.shuffle=1 + CONFIG_PROVE_LOCKING=y = arm64 hang
  2019-09-12 12:05       ` Qian Cai
@ 2019-09-16 14:42         ` Steven Rostedt
  2019-09-17  0:53           ` Sergey Senozhatsky
  2019-09-18 14:39           ` printk() + memory offline deadlock (WAS Re: page_alloc.shuffle=1 + CONFIG_PROVE_LOCKING=y = arm64 hang) Qian Cai
  0 siblings, 2 replies; 16+ messages in thread
From: Steven Rostedt @ 2019-09-16 14:42 UTC (permalink / raw)
  To: Qian Cai
  Cc: Sergey Senozhatsky, Petr Mladek, Catalin Marinas, Will Deacon,
	Dan Williams, linux-mm, linux-kernel, linux-arm-kernel,
	Peter Zijlstra, Waiman Long, Thomas Gleixner, Theodore Ts'o,
	Arnd Bergmann, Greg Kroah-Hartman

On Thu, 12 Sep 2019 08:05:41 -0400
Qian Cai <cai@lca.pw> 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.

-- Steve


^ permalink raw reply	[flat|nested] 16+ messages in thread

* Re: page_alloc.shuffle=1 + CONFIG_PROVE_LOCKING=y = arm64 hang
  2019-09-16 14:42         ` Steven Rostedt
@ 2019-09-17  0:53           ` Sergey Senozhatsky
  2019-09-18 14:39           ` printk() + memory offline deadlock (WAS Re: page_alloc.shuffle=1 + CONFIG_PROVE_LOCKING=y = arm64 hang) Qian Cai
  1 sibling, 0 replies; 16+ messages in thread
From: Sergey Senozhatsky @ 2019-09-17  0:53 UTC (permalink / raw)
  To: Steven Rostedt
  Cc: Qian Cai, Sergey Senozhatsky, Petr Mladek, Catalin Marinas,
	Will Deacon, Dan Williams, linux-mm, linux-kernel,
	linux-arm-kernel, Peter Zijlstra, Waiman Long, Thomas Gleixner,
	Theodore Ts'o, Arnd Bergmann, Greg Kroah-Hartman

On (09/16/19 10:42), Steven Rostedt wrote:
[..]
> > 
> > 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 guess it would make sense, since LTS and -stable kernels won't get new
printk().

	-ss


^ permalink raw reply	[flat|nested] 16+ messages in thread

* printk() + memory offline deadlock (WAS Re: page_alloc.shuffle=1 + CONFIG_PROVE_LOCKING=y = arm64 hang)
  2019-09-16 14:42         ` Steven Rostedt
  2019-09-17  0:53           ` Sergey Senozhatsky
@ 2019-09-18 14:39           ` Qian Cai
  2019-09-18 15:50             ` Sergey Senozhatsky
  1 sibling, 1 reply; 16+ messages in thread
From: Qian Cai @ 2019-09-18 14:39 UTC (permalink / raw)
  To: Steven Rostedt
  Cc: Sergey Senozhatsky, Petr Mladek, Catalin Marinas, Will Deacon,
	Dan Williams, linux-mm, linux-kernel, linux-arm-kernel,
	Peter Zijlstra, Waiman Long, Thomas Gleixner, Theodore Ts'o,
	Arnd Bergmann, Greg Kroah-Hartman

On Mon, 2019-09-16 at 10:42 -0400, Steven Rostedt wrote:
> On Thu, 12 Sep 2019 08:05:41 -0400
> Qian Cai <cai@lca.pw> 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


^ permalink raw reply	[flat|nested] 16+ messages in thread

* Re: printk() + memory offline deadlock (WAS Re: page_alloc.shuffle=1 + CONFIG_PROVE_LOCKING=y = arm64 hang)
  2019-09-18 14:39           ` printk() + memory offline deadlock (WAS Re: page_alloc.shuffle=1 + CONFIG_PROVE_LOCKING=y = arm64 hang) Qian Cai
@ 2019-09-18 15:50             ` Sergey Senozhatsky
  2019-09-18 15:58               ` Sergey Senozhatsky
  2019-09-18 16:10               ` Qian Cai
  0 siblings, 2 replies; 16+ messages in thread
From: Sergey Senozhatsky @ 2019-09-18 15:50 UTC (permalink / raw)
  To: Qian Cai
  Cc: Steven Rostedt, Sergey Senozhatsky, Petr Mladek, Catalin Marinas,
	Will Deacon, Dan Williams, linux-mm, linux-kernel,
	linux-arm-kernel, Peter Zijlstra, Waiman Long, Thomas Gleixner,
	Theodore Ts'o, Arnd Bergmann, Greg Kroah-Hartman

On (09/18/19 10:39), Qian Cai wrote:
> > 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.

Mother chicken...

Do you actually see a deadlock? I'd rather expect a lockdep splat, but
anyway...

> [  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

So you have debug objects enabled. Right? This thing does not behave
when it comes to printing. debug_objects are slightly problematic.

This thing does

	rq->lock --> zone->lock

It takes rq->lock and then calls into __sched_fork()->hrtimer_init()->debug_objects()->MM

This doesn't look very right - a dive into MM under rq->lock.

Peter, Thomas am I wrong?

> [  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

pi_lock --> rq->lock

> [  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

console_sem->lock --> pi_lock

This also covers console_sem->lock --> rq->lock, and maintains
pi_lock --> rq->lock

So we have

	console_sem->lock --> pi_lock --> rq->lock

> [  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

zone->lock --> console_sem->lock

So then we have

	zone->lock --> console_sem->lock --> pi_lock --> rq->lock

  vs. the reverse chain

	rq->lock --> console_sem->lock

If I get this right.

> [  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

Lovely.

	-ss


^ permalink raw reply	[flat|nested] 16+ messages in thread

* Re: printk() + memory offline deadlock (WAS Re: page_alloc.shuffle=1 + CONFIG_PROVE_LOCKING=y = arm64 hang)
  2019-09-18 15:50             ` Sergey Senozhatsky
@ 2019-09-18 15:58               ` Sergey Senozhatsky
  2019-09-18 16:10               ` Qian Cai
  1 sibling, 0 replies; 16+ messages in thread
From: Sergey Senozhatsky @ 2019-09-18 15:58 UTC (permalink / raw)
  To: Sergey Senozhatsky
  Cc: Qian Cai, Steven Rostedt, Petr Mladek, Catalin Marinas,
	Will Deacon, Dan Williams, linux-mm, linux-kernel,
	linux-arm-kernel, Peter Zijlstra, Waiman Long, Thomas Gleixner,
	Theodore Ts'o, Arnd Bergmann, Greg Kroah-Hartman

A correction:

On (09/19/19 00:51), Sergey Senozhatsky wrote:
[..]
>
> zone->lock --> console_sem->lock
> 
> So then we have
> 
> 	zone->lock --> console_sem->lock --> pi_lock --> rq->lock
> 
>   vs. the reverse chain
> 
> 	rq->lock --> console_sem->lock

                     ^^^ zone->lock

	-ss


^ permalink raw reply	[flat|nested] 16+ messages in thread

* Re: printk() + memory offline deadlock (WAS Re: page_alloc.shuffle=1 + CONFIG_PROVE_LOCKING=y = arm64 hang)
  2019-09-18 15:50             ` Sergey Senozhatsky
  2019-09-18 15:58               ` Sergey Senozhatsky
@ 2019-09-18 16:10               ` Qian Cai
  1 sibling, 0 replies; 16+ messages in thread
From: Qian Cai @ 2019-09-18 16:10 UTC (permalink / raw)
  To: Sergey Senozhatsky
  Cc: Steven Rostedt, Sergey Senozhatsky, Petr Mladek, Catalin Marinas,
	Will Deacon, Dan Williams, linux-mm, linux-kernel,
	linux-arm-kernel, Peter Zijlstra, Waiman Long, Thomas Gleixner,
	Theodore Ts'o, Arnd Bergmann, Greg Kroah-Hartman

On Thu, 2019-09-19 at 00:50 +0900, Sergey Senozhatsky wrote:
> On (09/18/19 10:39), Qian Cai wrote:
> > > 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.
> 
> Mother chicken...
> 
> Do you actually see a deadlock? I'd rather expect a lockdep splat, but
> anyway...

Not yet, just a lockdep splat so far.

> 
> > [  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
> 
> So you have debug objects enabled. Right? This thing does not behave
> when it comes to printing. debug_objects are slightly problematic.

Yes, but there is an also a similar splat without the debug_objects. It looks
like anything try to allocate memory in that path will trigger it anyway.

[  297.425908] WARNING: possible circular locking dependency detected
[  297.425908] 5.3.0-next-20190917 #8 Not tainted
[  297.425909] ------------------------------------------------------
[  297.425910] test.sh/8653 is trying to acquire lock:
[  297.425911] ffffffff865a4460 (console_owner){-.-.}, at:
console_unlock+0x207/0x750

[  297.425914] but task is already holding lock:
[  297.425915] ffff88883fff3c58 (&(&zone->lock)->rlock){-.-.}, at:
__offline_isolated_pages+0x179/0x3e0

[  297.425919] which lock already depends on the new lock.


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

[  297.425922] -> #3 (&(&zone->lock)->rlock){-.-.}:
[  297.425925]        __lock_acquire+0x5b3/0xb40
[  297.425925]        lock_acquire+0x126/0x280
[  297.425926]        _raw_spin_lock+0x2f/0x40
[  297.425927]        rmqueue_bulk.constprop.21+0xb6/0x1160
[  297.425928]        get_page_from_freelist+0x898/0x22c0
[  297.425928]        __alloc_pages_nodemask+0x2f3/0x1cd0
[  297.425929]        alloc_pages_current+0x9c/0x110
[  297.425930]        allocate_slab+0x4c6/0x19c0
[  297.425931]        new_slab+0x46/0x70
[  297.425931]        ___slab_alloc+0x58b/0x960
[  297.425932]        __slab_alloc+0x43/0x70
[  297.425933]        __kmalloc+0x3ad/0x4b0
[  297.425933]        __tty_buffer_request_room+0x100/0x250
[  297.425934]        tty_insert_flip_string_fixed_flag+0x67/0x110
[  297.425935]        pty_write+0xa2/0xf0
[  297.425936]        n_tty_write+0x36b/0x7b0
[  297.425936]        tty_write+0x284/0x4c0
[  297.425937]        __vfs_write+0x50/0xa0
[  297.425938]        vfs_write+0x105/0x290
[  297.425939]        redirected_tty_write+0x6a/0xc0
[  297.425939]        do_iter_write+0x248/0x2a0
[  297.425940]        vfs_writev+0x106/0x1e0
[  297.425941]        do_writev+0xd4/0x180
[  297.425941]        __x64_sys_writev+0x45/0x50
[  297.425942]        do_syscall_64+0xcc/0x76c
[  297.425943]        entry_SYSCALL_64_after_hwframe+0x49/0xbe

[  297.425944] -> #2 (&(&port->lock)->rlock){-.-.}:
[  297.425946]        __lock_acquire+0x5b3/0xb40
[  297.425947]        lock_acquire+0x126/0x280
[  297.425948]        _raw_spin_lock_irqsave+0x3a/0x50
[  297.425949]        tty_port_tty_get+0x20/0x60
[  297.425949]        tty_port_default_wakeup+0xf/0x30
[  297.425950]        tty_port_tty_wakeup+0x39/0x40
[  297.425951]        uart_write_wakeup+0x2a/0x40
[  297.425952]        serial8250_tx_chars+0x22e/0x440
[  297.425952]        serial8250_handle_irq.part.8+0x14a/0x170
[  297.425953]        serial8250_default_handle_irq+0x5c/0x90
[  297.425954]        serial8250_interrupt+0xa6/0x130
[  297.425955]        __handle_irq_event_percpu+0x78/0x4f0
[  297.425955]        handle_irq_event_percpu+0x70/0x100
[  297.425956]        handle_irq_event+0x5a/0x8b
[  297.425957]        handle_edge_irq+0x117/0x370
[  297.425958]        do_IRQ+0x9e/0x1e0
[  297.425958]        ret_from_intr+0x0/0x2a
[  297.425959]        cpuidle_enter_state+0x156/0x8e0
[  297.425960]        cpuidle_enter+0x41/0x70
[  297.425960]        call_cpuidle+0x5e/0x90
[  297.425961]        do_idle+0x333/0x370
[  297.425962]        cpu_startup_entry+0x1d/0x1f
[  297.425962]        start_secondary+0x290/0x330
[  297.425963]        secondary_startup_64+0xb6/0xc0

[  297.425964] -> #1 (&port_lock_key){-.-.}:
[  297.425967]        __lock_acquire+0x5b3/0xb40
[  297.425967]        lock_acquire+0x126/0x280
[  297.425968]        _raw_spin_lock_irqsave+0x3a/0x50
[  297.425969]        serial8250_console_write+0x3e4/0x450
[  297.425970]        univ8250_console_write+0x4b/0x60
[  297.425970]        console_unlock+0x501/0x750
[  297.425971]        vprintk_emit+0x10d/0x340
[  297.425972]        vprintk_default+0x1f/0x30
[  297.425972]        vprintk_func+0x44/0xd4
[  297.425973]        printk+0x9f/0xc5
[  297.425974]        register_console+0x39c/0x520
[  297.425975]        univ8250_console_init+0x23/0x2d
[  297.425975]        console_init+0x338/0x4cd
[  297.425976]        start_kernel+0x534/0x724
[  297.425977]        x86_64_start_reservations+0x24/0x26
[  297.425977]        x86_64_start_kernel+0xf4/0xfb
[  297.425978]        secondary_startup_64+0xb6/0xc0

[  297.425979] -> #0 (console_owner){-.-.}:
[  297.425982]        check_prev_add+0x107/0xea0
[  297.425982]        validate_chain+0x8fc/0x1200
[  297.425983]        __lock_acquire+0x5b3/0xb40
[  297.425984]        lock_acquire+0x126/0x280
[  297.425984]        console_unlock+0x269/0x750
[  297.425985]        vprintk_emit+0x10d/0x340
[  297.425986]        vprintk_default+0x1f/0x30
[  297.425987]        vprintk_func+0x44/0xd4
[  297.425987]        printk+0x9f/0xc5
[  297.425988]        __offline_isolated_pages.cold.52+0x2f/0x30a
[  297.425989]        offline_isolated_pages_cb+0x17/0x30
[  297.425990]        walk_system_ram_range+0xda/0x160
[  297.425990]        __offline_pages+0x79c/0xa10
[  297.425991]        offline_pages+0x11/0x20
[  297.425992]        memory_subsys_offline+0x7e/0xc0
[  297.425992]        device_offline+0xd5/0x110
[  297.425993]        state_store+0xc6/0xe0
[  297.425994]        dev_attr_store+0x3f/0x60
[  297.425995]        sysfs_kf_write+0x89/0xb0
[  297.425995]        kernfs_fop_write+0x188/0x240
[  297.425996]        __vfs_write+0x50/0xa0
[  297.425997]        vfs_write+0x105/0x290
[  297.425997]        ksys_write+0xc6/0x160
[  297.425998]        __x64_sys_write+0x43/0x50
[  297.425999]        do_syscall_64+0xcc/0x76c
[  297.426000]        entry_SYSCALL_64_after_hwframe+0x49/0xbe

[  297.426001] other info that might help us debug this:

[  297.426002] Chain exists of:
[  297.426002]   console_owner --> &(&port->lock)->rlock --> &(&zone->lock)-
>rlock

[  297.426007]  Possible unsafe locking scenario:

[  297.426008]        CPU0                    CPU1
[  297.426009]        ----                    ----
[  297.426009]   lock(&(&zone->lock)->rlock);
[  297.426011]                                lock(&(&port->lock)->rlock);
[  297.426013]                                lock(&(&zone->lock)->rlock);
[  297.426014]   lock(console_owner);

[  297.426016]  *** DEADLOCK ***

[  297.426017] 9 locks held by test.sh/8653:
[  297.426018]  #0: ffff88839ba7d408 (sb_writers#4){.+.+}, at:
vfs_write+0x25f/0x290
[  297.426021]  #1: ffff888277618880 (&of->mutex){+.+.}, at:
kernfs_fop_write+0x128/0x240
[  297.426024]  #2: ffff8898131fc218 (kn->count#115){.+.+}, at:
kernfs_fop_write+0x138/0x240
[  297.426028]  #3: ffffffff86962a80 (device_hotplug_lock){+.+.}, at:
lock_device_hotplug_sysfs+0x16/0x50
[  297.426031]  #4: ffff8884374f4990 (&dev->mutex){....}, at:
device_offline+0x70/0x110
[  297.426034]  #5: ffffffff86515250 (cpu_hotplug_lock.rw_sem){++++}, at:
__offline_pages+0xbf/0xa10
[  297.426037]  #6: ffffffff867405f0 (mem_hotplug_lock.rw_sem){++++}, at:
percpu_down_write+0x87/0x2f0
[  297.426040]  #7: ffff88883fff3c58 (&(&zone->lock)->rlock){-.-.}, at:
__offline_isolated_pages+0x179/0x3e0
[  297.426043]  #8: ffffffff865a4920 (console_lock){+.+.}, at:
vprintk_emit+0x100/0x340

[  297.426047] stack backtrace:
[  297.426048] CPU: 1 PID: 8653 Comm: test.sh Not tainted 5.3.0-next-20190917 #8
[  297.426049] Hardware name: HPE ProLiant DL560 Gen10/ProLiant DL560 Gen10,
BIOS U34 05/21/2019
[  297.426049] Call Trace:
[  297.426050]  dump_stack+0x86/0xca
[  297.426051]  print_circular_bug.cold.31+0x243/0x26e
[  297.426051]  check_noncircular+0x29e/0x2e0
[  297.426052]  ? stack_trace_save+0x87/0xb0
[  297.426053]  ? print_circular_bug+0x120/0x120
[  297.426053]  check_prev_add+0x107/0xea0
[  297.426054]  validate_chain+0x8fc/0x1200
[  297.426055]  ? check_prev_add+0xea0/0xea0
[  297.426055]  __lock_acquire+0x5b3/0xb40
[  297.426056]  lock_acquire+0x126/0x280
[  297.426057]  ? console_unlock+0x207/0x750
[  297.426057]  ? __kasan_check_read+0x11/0x20
[  297.426058]  console_unlock+0x269/0x750
[  297.426059]  ? console_unlock+0x207/0x750
[  297.426059]  vprintk_emit+0x10d/0x340
[  297.426060]  vprintk_default+0x1f/0x30
[  297.426061]  vprintk_func+0x44/0xd4
[  297.426061]  ? do_raw_spin_lock+0x118/0x1d0
[  297.426062]  printk+0x9f/0xc5
[  297.426063]  ? kmsg_dump_rewind_nolock+0x64/0x64
[  297.426064]  ? __offline_isolated_pages+0x179/0x3e0
[  297.426064]  __offline_isolated_pages.cold.52+0x2f/0x30a
[  297.426065]  ? online_memory_block+0x20/0x20
[  297.426066]  offline_isolated_pages_cb+0x17/0x30
[  297.426067]  walk_system_ram_range+0xda/0x160
[  297.426067]  ? walk_mem_res+0x30/0x30
[  297.426068]  ? dissolve_free_huge_page+0x1e/0x2b0
[  297.426069]  __offline_pages+0x79c/0xa10
[  297.426069]  ? __add_memory+0xc0/0xc0
[  297.426070]  ? __kasan_check_write+0x14/0x20
[  297.426071]  ? __mutex_lock+0x344/0xcd0
[  297.426071]  ? _raw_spin_unlock_irqrestore+0x49/0x50
[  297.426072]  ? device_offline+0x70/0x110
[  297.426073]  ? klist_next+0x1c1/0x1e0
[  297.426073]  ? __mutex_add_waiter+0xc0/0xc0
[  297.426074]  ? klist_next+0x10b/0x1e0
[  297.426075]  ? klist_iter_exit+0x16/0x40
[  297.426076]  ? device_for_each_child+0xd0/0x110
[  297.426076]  offline_pages+0x11/0x20
[  297.426077]  memory_subsys_offline+0x7e/0xc0
[  297.426078]  device_offline+0xd5/0x110
[  297.426078]  ? auto_online_blocks_show+0x70/0x70
[  297.426079]  state_store+0xc6/0xe0
[  297.426080]  dev_attr_store+0x3f/0x60
[  297.426080]  ? device_match_name+0x40/0x40
[  297.426081]  sysfs_kf_write+0x89/0xb0
[  297.426082]  ? sysfs_file_ops+0xa0/0xa0
[  297.426082]  kernfs_fop_write+0x188/0x240
[  297.426083]  __vfs_write+0x50/0xa0
[  297.426084]  vfs_write+0x105/0x290
[  297.426084]  ksys_write+0xc6/0x160
[  297.426085]  ? __x64_sys_read+0x50/0x50
[  297.426086]  ? do_syscall_64+0x79/0x76c
[  297.426086]  ? do_syscall_64+0x79/0x76c
[  297.426087]  __x64_sys_write+0x43/0x50
[  297.426088]  do_syscall_64+0xcc/0x76c
[  297.426088]  ? trace_hardirqs_on_thunk+0x1a/0x20
[  297.426089]  ? syscall_return_slowpath+0x210/0x210
[  297.426090]  ? entry_SYSCALL_64_after_hwframe+0x3e/0xbe
[  297.426091]  ? trace_hardirqs_off_caller+0x3a/0x150
[  297.426092]  ? trace_hardirqs_off_thunk+0x1a/0x20
[  297.426092]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
[  297.426093] RIP: 0033:0x7fd7336b4e18
[  297.426095] Code: 89 02 48 c7 c0 ff ff ff ff eb b3 0f 1f 80 00 00 00 00 f3 0f
1e fa 48 8d 05 05 59 2d 00 8b 00 85 c0 75 17 b8 01 00 00 00 0f 05 <48> 3d 00 f0
ff ff 77 58 c3 0f 1f 80 00 00 00 00 41 54 49 89 d4 55
[  297.426096] RSP: 002b:00007ffc58c7b258 EFLAGS: 00000246 ORIG_RAX:
0000000000000001
[  297.426098] RAX: ffffffffffffffda RBX: 0000000000000008 RCX: 00007fd7336b4e18
[  297.426098] RDX: 0000000000000008 RSI: 000055ad6d519c70 RDI: 0000000000000001
[  297.426099] RBP: 000055ad6d519c70 R08: 000000000000000a R09: 00007fd733746300
[  297.426100] R10: 000000000000000a R11: 0000000000000246 R12: 00007fd733986780
[  297.426101] R13: 0000000000000008 R14: 00007fd733981740 R15: 0000000000000008


[  763.659202][    C6] WARNING: possible circular locking dependency detected
[  763.659202][    C6] 5.3.0-next-20190917 #3 Not tainted
[  763.659203][    C6] ------------------------------------------------------
[  763.659203][    C6] test.sh/8352 is trying to acquire lock:
[  763.659203][    C6] ffffffffa187e5f8 ((console_sem).lock){..-.}, at:
down_trylock+0x14/0x40
[  763.659206][    C6] 
[  763.659206][    C6] but task is already holding lock:
[  763.659206][    C6] ffff9bcf7f373c58 (&(&zone->lock)->rlock){-.-.}, at:
__offline_isolated_pages+0x11e/0x2d0
[  763.659208][    C6] 
[  763.659208][    C6] which lock already depends on the new lock.
[  763.659209][    C6] 
[  763.659209][    C6] 
[  763.659209][    C6] the existing dependency chain (in reverse order) is:
[  763.659210][    C6] 
[  763.659210][    C6] -> #3 (&(&zone->lock)->rlock){-.-.}:
[  763.659211][    C6]        __lock_acquire+0x44e/0x8c0
[  763.659212][    C6]        lock_acquire+0xc0/0x1c0
[  763.659212][    C6]        _raw_spin_lock+0x2f/0x40
[  763.659212][    C6]        rmqueue_bulk.constprop.24+0x62/0xba0
[  763.659213][    C6]        get_page_from_freelist+0x581/0x1810
[  763.659213][    C6]        __alloc_pages_nodemask+0x20d/0x1750
[  763.659214][    C6]        alloc_page_interleave+0x17/0x100
[  763.659214][    C6]        alloc_pages_current+0xc0/0xe0
[  763.659214][    C6]        allocate_slab+0x4b2/0x1a20
[  763.659215][    C6]        new_slab+0x46/0x70
[  763.659215][    C6]        ___slab_alloc+0x58a/0x960
[  763.659215][    C6]        __slab_alloc+0x43/0x70
[  763.659216][    C6]        kmem_cache_alloc+0x33e/0x440
[  763.659216][    C6]        fill_pool+0x1ae/0x460
[  763.659216][    C6]        __debug_object_init+0x35/0x4a0
[  763.659217][    C6]        debug_object_init+0x16/0x20
[  763.659217][    C6]        hrtimer_init+0x25/0x130
[  763.659218][    C6]        init_dl_task_timer+0x20/0x30
[  763.659218][    C6]        __sched_fork+0x92/0x100
[  763.659218][    C6]        init_idle+0x8d/0x380
[  763.659219][    C6]        fork_idle+0xd9/0x140
[  763.659219][    C6]        idle_threads_init+0xd3/0x15e
[  763.659219][    C6]        smp_init+0x1b/0xbb
[  763.659220][    C6]        kernel_init_freeable+0x248/0x557
[  763.659220][    C6]        kernel_init+0xf/0x11e
[  763.659220][    C6]        ret_from_fork+0x27/0x50
[  763.659221][    C6] 
[  763.659221][    C6] -> #2 (&rq->lock){-.-.}:
[  763.659222][    C6]        __lock_acquire+0x44e/0x8c0
[  763.659223][    C6]        lock_acquire+0xc0/0x1c0
[  763.659223][    C6]        _raw_spin_lock+0x2f/0x40
[  763.659223][    C6]        task_fork_fair+0x37/0x150
[  763.659224][    C6]        sched_fork+0x126/0x230
[  763.659224][    C6]        copy_process+0xafc/0x1e90
[  763.659224][    C6]        _do_fork+0x89/0x720
[  763.659225][    C6]        kernel_thread+0x58/0x70
[  763.659225][    C6]        rest_init+0x28/0x302
[  763.659225][    C6]        arch_call_rest_init+0xe/0x1b
[  763.659226][    C6]        start_kernel+0x581/0x5a0
[  763.659226][    C6]        x86_64_start_reservations+0x24/0x26
[  763.659227][    C6]        x86_64_start_kernel+0xef/0xf6
[  763.659227][    C6]        secondary_startup_64+0xb6/0xc0
[  763.659227][    C6] 
[  763.659227][    C6] -> #1 (&p->pi_lock){-.-.}:
[  763.659229][    C6]        __lock_acquire+0x44e/0x8c0
[  763.659229][    C6]        lock_acquire+0xc0/0x1c0
[  763.659230][    C6]        _raw_spin_lock_irqsave+0x3a/0x50
[  763.659230][    C6]        try_to_wake_up+0x5c/0xbc0
[  763.659230][    C6]        wake_up_process+0x15/0x20
[  763.659231][    C6]        __up+0x4a/0x50
[  763.659231][    C6]        up+0x45/0x50
[  763.659231][    C6]        __up_console_sem+0x37/0x60
[  763.659232][    C6]        console_unlock+0x357/0x600
[  763.659232][    C6]        vprintk_emit+0x101/0x320
[  763.659232][    C6]        vprintk_default+0x1f/0x30
[  763.659233][    C6]        vprintk_func+0x44/0xd4
[  763.659233][    C6]        printk+0x58/0x6f
[  763.659234][    C6]        do_exit+0xd73/0xd80
[  763.659234][    C6]        do_group_exit+0x41/0xd0
[  763.659234][    C6]        __x64_sys_exit_group+0x18/0x20
[  763.659235][    C6]        do_syscall_64+0x6d/0x488
[  763.659235][    C6]        entry_SYSCALL_64_after_hwframe+0x49/0xbe
[  763.659235][    C6] 
[  763.659236][    C6] -> #0 ((console_sem).lock){..-.}:
[  763.659237][    C6]        check_prev_add+0x9b/0xa10
[  763.659237][    C6]        validate_chain+0x759/0xdc0
[  763.659238][    C6]        __lock_acquire+0x44e/0x8c0
[  763.659238][    C6]        lock_acquire+0xc0/0x1c0
[  763.659239][    C6]        _raw_spin_lock_irqsave+0x3a/0x50
[  763.659239][    C6]        down_trylock+0x14/0x40
[  763.659239][    C6]        __down_trylock_console_sem+0x2b/0xa0
[  763.659240][    C6]        console_trylock+0x16/0x60
[  763.659240][    C6]        vprintk_emit+0xf4/0x320
[  763.659240][    C6]        vprintk_default+0x1f/0x30
[  763.659241][    C6]        vprintk_func+0x44/0xd4
[  763.659241][    C6]        printk+0x58/0x6f
[  763.659242][    C6]        __offline_isolated_pages.cold.55+0x38/0x28e
[  763.659242][    C6]        offline_isolated_pages_cb+0x15/0x20
[  763.659242][    C6]        walk_system_ram_range+0x7b/0xd0
[  763.659243][    C6]        __offline_pages+0x456/0xc10
[  763.659243][    C6]        offline_pages+0x11/0x20
[  763.659243][    C6]        memory_subsys_offline+0x44/0x60
[  763.659244][    C6]        device_offline+0x90/0xc0
[  763.659244][    C6]        state_store+0xbc/0xe0
[  763.659244][    C6]        dev_attr_store+0x17/0x30
[  763.659245][    C6]        sysfs_kf_write+0x4b/0x60
[  763.659245][    C6]        kernfs_fop_write+0x119/0x1c0
[  763.659245][    C6]        __vfs_write+0x1b/0x40
[  763.659246][    C6]        vfs_write+0xbd/0x1c0
[  763.659246][    C6]        ksys_write+0x64/0xe0
[  763.659247][    C6]        __x64_sys_write+0x1a/0x20
[  763.659247][    C6]        do_syscall_64+0x6d/0x488
[  763.659247][    C6]        entry_SYSCALL_64_after_hwframe+0x49/0xbe
[  763.659248][    C6] 
[  763.659248][    C6] other info that might help us debug this:
[  763.659248][    C6] 
[  763.659248][    C6] Chain exists of:
[  763.659249][    C6]   (console_sem).lock --> &rq->lock --> &(&zone->lock)-
>rlock
[  763.659251][    C6] 
[  763.659251][    C6]  Possible unsafe locking scenario:
[  763.659251][    C6] 
[  763.659252][    C6]        CPU0                    CPU1
[  763.659252][    C6]        ----                    ----
[  763.659252][    C6]   lock(&(&zone->lock)->rlock);
[  763.659253][    C6]                                lock(&rq->lock);
[  763.659254][    C6]                                lock(&(&zone->lock)-
>rlock);
[  763.659255][    C6]   lock((console_sem).lock);
[  763.659256][    C6] 
[  763.659256][    C6]  *** DEADLOCK ***
[  763.659256][    C6] 
[  763.659257][    C6] 8 locks held by test.sh/8352:
[  763.659257][    C6]  #0: ffff9bdf4da39408 (sb_writers#4){.+.+}, at:
vfs_write+0x174/0x1c0
[  763.659259][    C6]  #1: ffff9be348280880 (&of->mutex){+.+.}, at:
kernfs_fop_write+0xe4/0x1c0
[  763.659260][    C6]  #2: ffff9bdb873757d0 (kn->count#125){.+.+}, at:
kernfs_fop_write+0xed/0x1c0
[  763.659262][    C6]  #3: ffffffffa194dec0 (device_hotplug_lock){+.+.}, at:
lock_device_hotplug_sysfs+0x15/0x40
[  763.659264][    C6]  #4: ffff9bcf7314c990 (&dev->mutex){....}, at:
device_offline+0x4e/0xc0
[  763.659265][    C6]  #5: ffffffffa185b9f0 (cpu_hotplug_lock.rw_sem){++++},
at: __offline_pages+0x3b/0xc10
[  763.659267][    C6]  #6: ffffffffa18e0b90 (mem_hotplug_lock.rw_sem){++++},
at: percpu_down_write+0x36/0x1c0
[  763.659268][    C6]  #7: ffff9bcf7f373c58 (&(&zone->lock)->rlock){-.-.}, at:
__offline_isolated_pages+0x11e/0x2d0
[  763.659270][    C6] 
[  763.659270][    C6] stack backtrace:
[  763.659271][    C6] CPU: 6 PID: 8352 Comm: test.sh Not tainted 5.3.0-next-
20190917 #3
[  763.659271][    C6] Hardware name: HPE ProLiant DL385 Gen10/ProLiant DL385
Gen10, BIOS A40 07/10/2019
[  763.659272][    C6] Call Trace:
[  763.659272][    C6]  dump_stack+0x70/0x9a
[  763.659272][    C6]  print_circular_bug.cold.31+0x1c0/0x1eb
[  763.659273][    C6]  check_noncircular+0x18c/0x1a0
[  763.659273][    C6]  check_prev_add+0x9b/0xa10
[  763.659273][    C6]  validate_chain+0x759/0xdc0
[  763.659274][    C6]  __lock_acquire+0x44e/0x8c0
[  763.659274][    C6]  lock_acquire+0xc0/0x1c0
[  763.659274][    C6]  ? down_trylock+0x14/0x40
[  763.659275][    C6]  ? vprintk_emit+0xf4/0x320
[  763.659275][    C6]  _raw_spin_lock_irqsave+0x3a/0x50
[  763.659275][    C6]  ? down_trylock+0x14/0x40
[  763.659276][    C6]  down_trylock+0x14/0x40
[  763.659276][    C6]  __down_trylock_console_sem+0x2b/0xa0
[  763.659276][    C6]  console_trylock+0x16/0x60
[  763.659277][    C6]  vprintk_emit+0xf4/0x320
[  763.659277][    C6]  vprintk_default+0x1f/0x30
[  763.659277][    C6]  vprintk_func+0x44/0xd4
[  763.659278][    C6]  printk+0x58/0x6f
[  763.659278][    C6]  __offline_isolated_pages.cold.55+0x38/0x28e
[  763.659278][    C6]  ? online_memory_block+0x20/0x20
[  763.659279][    C6]  offline_isolated_pages_cb+0x15/0x20
[  763.659279][    C6]  walk_system_ram_range+0x7b/0xd0
[  763.659279][    C6]  __offline_pages+0x456/0xc10
[  763.659280][    C6]  offline_pages+0x11/0x20
[  763.659280][    C6]  memory_subsys_offline+0x44/0x60
[  763.659280][    C6]  device_offline+0x90/0xc0
[  763.659281][    C6]  state_store+0xbc/0xe0
[  763.659281][    C6]  dev_attr_store+0x17/0x30
[  763.659281][    C6]  sysfs_kf_write+0x4b/0x60
[  763.659282][    C6]  kernfs_fop_write+0x119/0x1c0
[  763.659282][    C6]  __vfs_write+0x1b/0x40
[  763.659282][    C6]  vfs_write+0xbd/0x1c0
[  763.659283][    C6]  ksys_write+0x64/0xe0
[  763.659283][    C6]  __x64_sys_write+0x1a/0x20
[  763.659283][    C6]  do_syscall_64+0x6d/0x488
[  763.659284][    C6]  ? trace_hardirqs_off_thunk+0x1a/0x20
[  763.659284][    C6]  entry_SYSCALL_64_after_hwframe+0x49/0xbe

> 
> This thing does
> 
> 	rq->lock --> zone->lock
> 
> It takes rq->lock and then calls into __sched_fork()->hrtimer_init()->debug_objects()->MM
> 
> This doesn't look very right - a dive into MM under rq->lock.
> 
> Peter, Thomas am I wrong?
> 
> > [  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
> 
> pi_lock --> rq->lock
> 
> > [  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
> 
> console_sem->lock --> pi_lock
> 
> This also covers console_sem->lock --> rq->lock, and maintains
> pi_lock --> rq->lock
> 
> So we have
> 
> 	console_sem->lock --> pi_lock --> rq->lock
> 
> > [  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
> 
> zone->lock --> console_sem->lock
> 
> So then we have
> 
> 	zone->lock --> console_sem->lock --> pi_lock --> rq->lock
> 
>   vs. the reverse chain
> 
> 	rq->lock --> console_sem->lock
> 
> If I get this right.
> 
> > [  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
> 
> Lovely.
> 
> 	-ss


^ permalink raw reply	[flat|nested] 16+ messages in thread

end of thread, back to index

Thread overview: 16+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2019-08-22 21:33 page_alloc.shuffle=1 + CONFIG_PROVE_LOCKING=y = arm64 hang Qian Cai
2019-08-23 11:37 ` Will Deacon
2019-08-23 11:52   ` Qian Cai
2019-09-05 21:08 ` Qian Cai
2019-09-10 15:22   ` Qian Cai
2019-09-10 19:49     ` Qian Cai
2019-09-12  2:28       ` CONFIG_SHUFFLE_PAGE_ALLOCATOR=y lockdep splat (WAS Re: page_alloc.shuffle=1 + CONFIG_PROVE_LOCKING=y = arm64 hang) Qian Cai
2019-09-10 20:35     ` page_alloc.shuffle=1 + CONFIG_PROVE_LOCKING=y = arm64 hang Qian Cai
2019-09-11  1:10     ` Sergey Senozhatsky
2019-09-12 12:05       ` Qian Cai
2019-09-16 14:42         ` Steven Rostedt
2019-09-17  0:53           ` Sergey Senozhatsky
2019-09-18 14:39           ` printk() + memory offline deadlock (WAS Re: page_alloc.shuffle=1 + CONFIG_PROVE_LOCKING=y = arm64 hang) Qian Cai
2019-09-18 15:50             ` Sergey Senozhatsky
2019-09-18 15:58               ` Sergey Senozhatsky
2019-09-18 16:10               ` Qian Cai

Linux-mm Archive on lore.kernel.org

Archives are clonable:
	git clone --mirror https://lore.kernel.org/linux-mm/0 linux-mm/git/0.git

	# If you have public-inbox 1.1+ installed, you may
	# initialize and index your mirror using the following commands:
	public-inbox-init -V2 linux-mm linux-mm/ https://lore.kernel.org/linux-mm \
		linux-mm@kvack.org linux-mm@archiver.kernel.org
	public-inbox-index linux-mm


Newsgroup available over NNTP:
	nntp://nntp.lore.kernel.org/org.kvack.linux-mm


AGPL code for this site: git clone https://public-inbox.org/ public-inbox