Return-Path: <cyrus@holtmann.org>
Message-ID: <55B64AF2.5090303@hurleysoftware.com>
Date: Mon, 27 Jul 2015 11:14:58 -0400
From: Peter Hurley <peter@hurleysoftware.com>
MIME-Version: 1.0
To: Jack Mitchell <ml@embed.me.uk>, linux-bluetooth@vger.kernel.org
CC: marcel@holtmann.org, gustavo@padovan.org
Subject: Re: btwilink: deadlock with omap-serial 4.2.0-rc4
References: <55B62BB0.205@embed.me.uk>
In-Reply-To: <55B62BB0.205@embed.me.uk>
Content-Type: text/plain; charset=utf-8
List-ID: <linux-bluetooth.vger.kernel.org>

Hi Jack,

On 07/27/2015 09:01 AM, Jack Mitchell wrote:
> Ran into this deadlock in the btwilink coupled with the omap-serial driver.Kernel is only tainted with a custom dts and small kim dts enablement patch, nothing which would cause this error.

Lock inversion in st_tx_wakeup(). This is a common bug in line disciplines.
The typical fix is to schedule the actual work to perform in a kworker.

Regards,
Peter Hurley

> Please CC as I'm not on list.
> 
> [ 1144.307220]
> [ 1144.308837] ======================================================
> [ 1144.310821] [ INFO: possible circular locking dependency detected ]
> [ 1144.321960] 4.2.0-rc4-00001-gaa22fe1-dirty #1 Not tainted
> [ 1144.321960] -------------------------------------------------------
> [ 1144.334259] connmand/322 is trying to acquire lock:
> [ 1144.334259] (&(&st_gdata->lock)->rlock){-.....}, at: [<c040f0b8>] st_tx_wakeup+0x48/0xf4
> [ 1144.340820]
> [ 1144.340820] but task is already holding lock:
> [ 1144.354248]  (&port_lock_key){-.-...}, at: [<c03e64a8>] serial_omap_irq+0x14/0x3ec
> [ 1144.362304]
> [ 1144.362304] which lock already depends on the new lock.
> [ 1144.362304]
> [ 1144.370819]
> [ 1144.370819] the existing dependency chain (in reverse order) is:
> [ 1144.370941]
> -> #1 (&port_lock_key){-.-...}:
> [ 1144.383453]        [<c03dc41c>] uart_write+0x34/0xdc
> [ 1144.383453]        [<c040f0dc>] st_tx_wakeup+0x6c/0xf4
> [ 1144.390777]        [<c040f57c>] st_write+0xa0/0x100
> [ 1144.390777]        [<bf44b0f0>] ti_st_send_frame+0x3c/0xdc [btwilink]
> [ 1144.406127]        [<bf3c441c>] hci_send_frame+0x6c/0xbc [bluetooth]
> [ 1144.413116]        [<bf3c44e8>] hci_cmd_work+0x7c/0xe0 [bluetooth]
> [ 1144.415313]        [<c0058f9c>] process_one_work+0x1b4/0x4b4
> [ 1144.420776]        [<c00592d8>] worker_thread+0x3c/0x4a4
> [ 1144.430786]        [<c005ef24>] kthread+0xd4/0xf0
> [ 1144.431396]        [<c000f618>] ret_from_fork+0x14/0x3c
> [ 1144.440673]
> -> #0 (&(&st_gdata->lock)->rlock){-.....}:
> [ 1144.447540]        [<c0602090>] _raw_spin_lock_irqsave+0x40/0x54
> [ 1144.450805]        [<c040f0b8>] st_tx_wakeup+0x48/0xf4
> [ 1144.459350]        [<c03be994>] tty_wakeup+0x50/0x5c
> [ 1144.464630]        [<c03e67e0>] serial_omap_irq+0x34c/0x3ec
> [ 1144.464630]        [<c009c338>] handle_irq_event_percpu+0x40/0x1e8
> [ 1144.470794]        [<c009c520>] handle_irq_event+0x40/0x64
> [ 1144.480773]        [<c009f5dc>] handle_fasteoi_irq+0xcc/0x1c4
> [ 1144.480773]        [<c009b9d4>] generic_handle_irq+0x28/0x3c
> [ 1144.494689]        [<c009bcbc>] __handle_domain_irq+0x64/0xe0
> [ 1144.500915]        [<c00094dc>] gic_handle_irq+0x20/0x60
> [ 1144.500915]        [<c0602cc8>] __irq_usr+0x48/0x60
> [ 1144.511596]        [<b6d9b094>] 0xb6d9b094
> [ 1144.515319]
> [ 1144.515319] other info that might help us debug this:
> [ 1144.515319]
> [ 1144.524261]  Possible unsafe locking scenario:
> [ 1144.524261]
> [ 1144.530456]        CPU0                    CPU1
> [ 1144.530670]        ----                    ----
> [ 1144.538269]   lock(&port_lock_key);
> [ 1144.540832] lock(&(&st_gdata->lock)->rlock);
> [ 1144.550872] lock(&port_lock_key);
> [ 1144.551422] lock(&(&st_gdata->lock)->rlock);
> [ 1144.551422]
> [ 1144.551422]  *** DEADLOCK ***
> [ 1144.551422]
> [ 1144.565277] 2 locks held by connmand/322:
> [ 1144.569366]  #0:  (&port_lock_key){-.-...}, at: [<c03e64a8>] serial_omap_irq+0x14/0x3ec
> [ 1144.569366]  #1:  (&tty->ldisc_sem){++++++}, at: [<c03c7c80>] tty_ldisc_ref+0x14/0x48
> [ 1144.588378]
> [ 1144.588378] stack backtrace:
> [ 1144.593383] CPU: 0 PID: 322 Comm: connmand Not tainted 4.2.0-rc4-00001-gaa22fe1-dirty #1
> [ 1144.601837] Hardware name: Generic OMAP4 (Flattened Device Tree)
> [ 1144.608123] [<c0016e8c>] (unwind_backtrace) from [<c001335c>] (show_stack+0x10/0x14)
> [ 1144.616241] [<c001335c>] (show_stack) from [<c05fb570>] (dump_stack+0x84/0x9c)
> [ 1144.622070] [<c05fb570>] (dump_stack) from [<c008cf1c>] (print_circular_bug+0x1c8/0x30c)
> [ 1144.631408] [<c008cf1c>] (print_circular_bug) from [<c00908b4>] (__lock_acquire+0x1ba0/0x1eb0)
> [ 1144.641296] [<c00908b4>] (__lock_acquire) from [<c00914a0>] (lock_acquire+0xa8/0x120)
> [ 1144.649475] [<c00914a0>] (lock_acquire) from [<c0602090>] (_raw_spin_lock_irqsave+0x40/0x54)
> [ 1144.658325] [<c0602090>] (_raw_spin_lock_irqsave) from [<c040f0b8>] (st_tx_wakeup+0x48/0xf4)
> [ 1144.666839] [<c040f0b8>] (st_tx_wakeup) from [<c03be994>] (tty_wakeup+0x50/0x5c)
> [ 1144.674468] [<c03be994>] (tty_wakeup) from [<c03e67e0>] (serial_omap_irq+0x34c/0x3ec)
> [ 1144.681823] [<c03e67e0>] (serial_omap_irq) from [<c009c338>] (handle_irq_event_percpu+0x40/0x1e8)
> [ 1144.692382] [<c009c338>] (handle_irq_event_percpu) from [<c009c520>] (handle_irq_event+0x40/0x64)
> [ 1144.700897] [<c009c520>] (handle_irq_event) from [<c009f5dc>] (handle_fasteoi_irq+0xcc/0x1c4)
> [ 1144.708312] [<c009f5dc>] (handle_fasteoi_irq) from [<c009b9d4>] (generic_handle_irq+0x28/0x3c)
> [ 1144.710998] [<c009b9d4>] (generic_handle_irq) from [<c009bcbc>] (__handle_domain_irq+0x64/0xe0)
> [ 1144.722015] [<c009bcbc>] (__handle_domain_irq) from [<c00094dc>] (gic_handle_irq+0x20/0x60)
> [ 1144.731201] [<c00094dc>] (gic_handle_irq) from [<c0602cc8>] (__irq_usr+0x48/0x60)
> [ 1144.745239] Exception stack(0xdcda5fb0 to 0xdcda5ff8)
> [ 1144.750457] 5fa0: 000d30c8 000d1bc4 00000000 00000000
> [ 1144.754516] 5fc0: 000d30c8 000000e4 000000e4 bedd2ae4 bedd2aec bedd2ae8 00000000 b6e4e85c
> [ 1144.767639] 5fe0: 00000000 bedd2ad8 b6d9b958 b6d9b094 20070110 ffffffff
> [ 1165.444732] BUG: spinlock lockup suspected on CPU#0, connmand/322
> [ 1165.453247]  lock: 0xddbf2410, .magic: dead4ead, .owner: connmand/322, .owner_cpu: 0
> [ 1165.460327] CPU: 0 PID: 322 Comm: connmand Not tainted 4.2.0-rc4-00001-gaa22fe1-dirty #1
> [ 1165.461822] Hardware name: Generic OMAP4 (Flattened Device Tree)
> [ 1165.475250] [<c0016e8c>] (unwind_backtrace) from [<c001335c>] (show_stack+0x10/0x14)
> [ 1165.483093] [<c001335c>] (show_stack) from [<c05fb570>] (dump_stack+0x84/0x9c)
> [ 1165.491729] [<c05fb570>] (dump_stack) from [<c00944a4>] (do_raw_spin_lock+0xec/0x1b0)
> [ 1165.499908] [<c00944a4>] (do_raw_spin_lock) from [<c0602098>] (_raw_spin_lock_irqsave+0x48/0x54)
> [ 1165.508636] [<c0602098>] (_raw_spin_lock_irqsave) from [<c03dc41c>] (uart_write+0x34/0xdc)
> [ 1165.515411] [<c03dc41c>] (uart_write) from [<c040f0dc>] (st_tx_wakeup+0x6c/0xf4)
> [ 1165.525482] [<c040f0dc>] (st_tx_wakeup) from [<c03be994>] (tty_wakeup+0x50/0x5c)
> [ 1165.530853] [<c03be994>] (tty_wakeup) from [<c03e67e0>] (serial_omap_irq+0x34c/0x3ec)
> [ 1165.541412] [<c03e67e0>] (serial_omap_irq) from [<c009c338>] (handle_irq_event_percpu+0x40/0x1e8)
> [ 1165.550689] [<c009c338>] (handle_irq_event_percpu) from [<c009c520>] (handle_irq_event+0x40/0x64)
> [ 1165.559967] [<c009c520>] (handle_irq_event) from [<c009f5dc>] (handle_fasteoi_irq+0xcc/0x1c4)
> [ 1165.568878] [<c009f5dc>] (handle_fasteoi_irq) from [<c009b9d4>] (generic_handle_irq+0x28/0x3c)
> [ 1165.576568] [<c009b9d4>] (generic_handle_irq) from [<c009bcbc>] (__handle_domain_irq+0x64/0xe0)
> [ 1165.581909] [<c009bcbc>] (__handle_domain_irq) from [<c00094dc>] (gic_handle_irq+0x20/0x60)
> [ 1165.593353] [<c00094dc>] (gic_handle_irq) from [<c0602cc8>] (__irq_usr+0x48/0x60)
> [ 1165.593353] Exception stack(0xdcda5fb0 to 0xdcda5ff8)
> [ 1165.604461] 5fa0: 000d30c8 000d1bc4 00000000 00000000
> [ 1165.617401] 5fc0: 000d30c8 000000e4 000000e4 bedd2ae4 bedd2aec bedd2ae8 00000000 b6e4e85c
> [ 1165.620697] 5fe0: 00000000 bedd2ad8 b6d9b958 b6d9b094 20070110 ffffffff
> [ 1170.528594] INFO: rcu_sched detected stalls on CPUs/tasks:
> [ 1170.534362]  0: (1 GPs behind) idle=7f7/140000000000001/0 softirq=2274/2274 fqs=19
> [ 1170.534362]  (detected by 1, t=2622 jiffies, g=707, c=706, q=5)
> [ 1170.534362] Task dump for CPU 0:
> [ 1170.534362] connmand        R running      0   322 1 0x00000002
> [ 1170.558593] [<c05fcd6c>] (__schedule) from [<c03639e0>] (vsnprintf+0x2e4/0x3c8)
> [ 1170.558593] [<c03639e0>] (vsnprintf) from [<c0364074>] (sprintf+0x24/0x34)
> [ 1170.566253] [<c0364074>] (sprintf) from [<c00c9e68>] (__sprint_symbol+0xa0/0xc8)
> [ 1170.566253] [<c00c9e68>] (__sprint_symbol) from [<00000000>] (  (null))
> [ 1170.581176] rcu_sched kthread starved for 2603 jiffies! g707 c706 f0x0