Re: [PATCH v2] mm/page_isolation: fix a deadlock with printk()

From: Qian Cai
Date: Wed Oct 09 2019 - 10:19:50 EST

Next message: Don Dutile: "Re: [PATCH] PCI/IOV: update num_VFs earlier"
Previous message: Petr Mladek: "Re: [PATCH v3 5/5] livepatch: Selftests of the API for tracking system state changes"
In reply to: Michal Hocko: "Re: [PATCH v2] mm/page_isolation: fix a deadlock with printk()"
Next in thread: Michal Hocko: "Re: [PATCH v2] mm/page_isolation: fix a deadlock with printk()"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

On Wed, 2019-10-09 at 15:51 +0200, Michal Hocko wrote:
> On Wed 09-10-19 09:43:13, Qian Cai wrote:
> > On Wed, 2019-10-09 at 15:27 +0200, Michal Hocko wrote:
> > > On Wed 09-10-19 09:06:42, Qian Cai wrote:
> > > [...]
> > > > https://lore.kernel.org/linux-mm/1570460350.5576.290.camel@xxxxxx/
> > > >
> > > > [ÂÂ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
> > > >
> > > > whereÂthe report again show the early boot call trace for the locking
> > > > dependency,
> > > >
> > > > console_owner --> port_lock_key
> > > >
> > > > but that dependency clearly not only happen in the early boot.
> > >
> > > Can you provide an example of the runtime dependency without any early
> > > boot artifacts? Because this discussion really doens't make much sense
> > > without a clear example of a _real_ lockdep report that is not a false
> > > possitive. All of them so far have been concluded to be false possitive
> > > AFAIU.
> >
> > An obvious one is in the above link. Just replace the trace in #1 above with
> > printk() from anywhere, i.e., just ignore the early boot calls there as they are
> > not important.
> >
> > printk()
> > console_unlock()
> > console_lock_spinning_enable() --> console_owner_lock
> > call_console_drivers()
> > serial8250_console_write() --> port->lock
>
> Can you paste the full lock chain graph to be sure we are on the same
> page?

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

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

which lock already depends on the new lock.

the existing dependency chain (in reverse order) is:

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

-> #2 (&(&port->lock)->rlock){-.-.}:
ÂÂÂÂÂÂÂ__lock_acquire+0x5b3/0xb40
ÂÂÂÂÂÂÂlock_acquire+0x126/0x280
ÂÂÂÂÂÂÂ_raw_spin_lock_irqsave+0x3a/0x50
ÂÂÂÂÂÂÂtty_port_tty_get+0x20/0x60
ÂÂÂÂÂÂÂtty_port_default_wakeup+0xf/0x30
ÂÂÂÂÂÂÂtty_port_tty_wakeup+0x39/0x40
ÂÂÂÂÂÂÂuart_write_wakeup+0x2a/0x40
ÂÂÂÂÂÂÂserial8250_tx_chars+0x22e/0x440
ÂÂÂÂÂÂÂserial8250_handle_irq.part.8+0x14a/0x170
ÂÂÂÂÂÂÂserial8250_default_handle_irq+0x5c/0x90
ÂÂÂÂÂÂÂserial8250_interrupt+0xa6/0x130
ÂÂÂÂÂÂÂ__handle_irq_event_percpu+0x78/0x4f0
ÂÂÂÂÂÂÂhandle_irq_event_percpu+0x70/0x100
ÂÂÂÂÂÂÂhandle_irq_event+0x5a/0x8b
ÂÂÂÂÂÂÂhandle_edge_irq+0x117/0x370
ÂÂÂÂÂÂÂdo_IRQ+0x9e/0x1e0
ÂÂÂÂÂÂÂret_from_intr+0x0/0x2a
ÂÂÂÂÂÂÂcpuidle_enter_state+0x156/0x8e0
ÂÂÂÂÂÂÂcpuidle_enter+0x41/0x70
ÂÂÂÂÂÂÂcall_cpuidle+0x5e/0x90
ÂÂÂÂÂÂÂdo_idle+0x333/0x370
ÂÂÂÂÂÂÂcpu_startup_entry+0x1d/0x1f
ÂÂÂÂÂÂÂstart_secondary+0x290/0x330
ÂÂÂÂÂÂÂsecondary_startup_64+0xb6/0xc0

-> #1 (&port_lock_key){-.-.}:
ÂÂÂÂÂÂÂ__lock_acquire+0x5b3/0xb40
ÂÂÂÂÂÂÂlock_acquire+0x126/0x280
ÂÂÂÂÂÂÂ_raw_spin_lock_irqsave+0x3a/0x50
ÂÂÂÂÂÂÂserial8250_console_write+0x3e4/0x450
ÂÂÂÂÂÂÂuniv8250_console_write+0x4b/0x60
ÂÂÂÂÂÂÂconsole_unlock+0x501/0x750
ÂÂÂÂÂÂÂvprintk_emit+0x10d/0x340
ÂÂÂÂÂÂÂvprintk_default+0x1f/0x30
ÂÂÂÂÂÂÂvprintk_func+0x44/0xd4
ÂÂÂÂÂÂÂprintk+0x9f/0xc5

-> #0 (console_owner){-.-.}:
ÂÂÂÂÂÂÂcheck_prev_add+0x107/0xea0
ÂÂÂÂÂÂÂvalidate_chain+0x8fc/0x1200
ÂÂÂÂÂÂÂ__lock_acquire+0x5b3/0xb40
ÂÂÂÂÂÂÂlock_acquire+0x126/0x280
ÂÂÂÂÂÂÂconsole_unlock+0x269/0x750
ÂÂÂÂÂÂÂvprintk_emit+0x10d/0x340
ÂÂÂÂÂÂÂvprintk_default+0x1f/0x30
ÂÂÂÂÂÂÂvprintk_func+0x44/0xd4
ÂÂÂÂÂÂÂprintk+0x9f/0xc5
ÂÂÂÂÂÂÂ__offline_isolated_pages.cold.52+0x2f/0x30a
ÂÂÂÂÂÂÂoffline_isolated_pages_cb+0x17/0x30
ÂÂÂÂÂÂÂwalk_system_ram_range+0xda/0x160
ÂÂÂÂÂÂÂ__offline_pages+0x79c/0xa10
ÂÂÂÂÂÂÂoffline_pages+0x11/0x20
ÂÂÂÂÂÂÂmemory_subsys_offline+0x7e/0xc0
ÂÂÂÂÂÂÂdevice_offline+0xd5/0x110
ÂÂÂÂÂÂÂstate_store+0xc6/0xe0
ÂÂÂÂÂÂÂdev_attr_store+0x3f/0x60
ÂÂÂÂÂÂÂsysfs_kf_write+0x89/0xb0
ÂÂÂÂÂÂÂkernfs_fop_write+0x188/0x240
ÂÂÂÂÂÂÂ__vfs_write+0x50/0xa0
ÂÂÂÂÂÂÂvfs_write+0x105/0x290
ÂÂÂÂÂÂÂksys_write+0xc6/0x160
ÂÂÂÂÂÂÂ__x64_sys_write+0x43/0x50
ÂÂÂÂÂÂÂdo_syscall_64+0xcc/0x76c
ÂÂÂÂÂÂÂentry_SYSCALL_64_after_hwframe+0x49/0xbe

other info that might help us debug this:

Chain exists of:
Â console_owner --> &(&port->lock)->rlock --> &(&zone->lock)-
>rlock

ÂPossible unsafe locking scenario:

ÂÂÂÂÂÂÂCPU0ÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂCPU1
ÂÂÂÂÂÂÂ----ÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂ----
Â lock(&(&zone->lock)->rlock);
ÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂlock(&(&port->lock)->rlock);
ÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂlock(&(&zone->lock)->rlock);
Â lock(console_owner);

Â*** DEADLOCK ***

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

stack backtrace:
CPU: 1 PID: 8653 Comm: test.sh Not tainted 5.3.0-next-20190917 #8
Hardware name: HPE ProLiant DL560 Gen10/ProLiant DL560 Gen10,
BIOS U34 05/21/2019
Call Trace:
Âdump_stack+0x86/0xca
Âprint_circular_bug.cold.31+0x243/0x26e
Âcheck_noncircular+0x29e/0x2e0
Âcheck_prev_add+0x107/0xea0
Âvalidate_chain+0x8fc/0x1200
Â__lock_acquire+0x5b3/0xb40
Âlock_acquire+0x126/0x280
Âconsole_unlock+0x269/0x750
Âvprintk_emit+0x10d/0x340
Âvprintk_default+0x1f/0x30
Âvprintk_func+0x44/0xd4
Âprintk+0x9f/0xc5
Â__offline_isolated_pages.cold.52+0x2f/0x30a
Âoffline_isolated_pages_cb+0x17/0x30
Âwalk_system_ram_range+0xda/0x160
Â__offline_pages+0x79c/0xa10
Âoffline_pages+0x11/0x20
Âmemory_subsys_offline+0x7e/0xc0
Âdevice_offline+0xd5/0x110
Âstate_store+0xc6/0xe0
Âdev_attr_store+0x3f/0x60
Âsysfs_kf_write+0x89/0xb0
Âkernfs_fop_write+0x188/0x240
Â__vfs_write+0x50/0xa0
Âvfs_write+0x105/0x290
Âksys_write+0xc6/0x160
Â__x64_sys_write+0x43/0x50
Âdo_syscall_64+0xcc/0x76c
Âentry_SYSCALL_64_after_hwframe+0x49/0xbe

Next message: Don Dutile: "Re: [PATCH] PCI/IOV: update num_VFs earlier"
Previous message: Petr Mladek: "Re: [PATCH v3 5/5] livepatch: Selftests of the API for tracking system state changes"
In reply to: Michal Hocko: "Re: [PATCH v2] mm/page_isolation: fix a deadlock with printk()"
Next in thread: Michal Hocko: "Re: [PATCH v2] mm/page_isolation: fix a deadlock with printk()"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]