[RFC] issues with locks

[Dan Williams]

On Fri, 2008-01-25 at 14:24 +0100, Holger Schurig wrote:
> Hi Dan and others !
> 
> I recently notices that I have issues with locks. I enabled a
> bunch of debugging options in my kernel:
> 
> ------------------
> CONFIG_SMP=y
> CONFIG_SUSPEND_SMP_POSSIBLE=y
> CONFIG_DEBUG_SHIRQ=y
> CONFIG_DETECT_SOFTLOCKUP=y
> CONFIG_DEBUG_PREEMPT=y
> CONFIG_DEBUG_RT_MUTEXES=y
> CONFIG_DEBUG_PI_LIST=y
> CONFIG_DEBUG_SPINLOCK=y
> CONFIG_DEBUG_MUTEXES=y
> CONFIG_DEBUG_LOCK_ALLOC=y
> CONFIG_PROVE_LOCKING=y
> CONFIG_LOCKDEP=y
> CONFIG_DEBUG_LOCKDEP=y
> CONFIG_TRACE_IRQFLAGS=y
> CONFIG_DEBUG_SPINLOCK_SLEEP=y
> CONFIG_DEBUG_BUGVERBOSE=y
> CONFIG_DEBUG_LIST=y
> CONFIG_DEBUG_STACKOVERFLOW=y
> CONFIG_DEBUG_STACK_USAGE=y
> CONFIG_DEBUG_PAGEALLOC=y
> CONFIG_DEBUG_RODATA=y
> CONFIG_DOUBLEFAULT=y
> ------------------
> 
> and then I started to make simple tests with CF and USB. One
> result of this is the recently posted "libertas: fix interrupt
> while removing driver" patch.
> 
> However, I have problems in the area of locking where I don't
> have enought knowledge to find out what's going on.
> 
> Let's start with the easy thing. I think the right fix for this:
> 
> ------------------
> [ INFO: possible recursive locking detected ]
> 2.6.24-rc8 #15
> 
> lbs_main/3782 is trying to acquire lock:
>  (&priv->driver_lock){+...}, at: [<f88fb2dc>] if_cs_get_int_status+0x29f/0x487 [libertas_cs
> 
> but task is already holding lock:
>  (&priv->driver_lock){+...}, at: [<f89174b5>] lbs_thread+0x332/0x7ea [libertas]
> ------------------

Yeah, I just got this plugging the CF card in with 2.6.24 on Fedora 9.
Will take a look if I have some time today.

Dan

> is this patch:
> 
> 
> 
> 
> Subject: [PATCH] libertas: fix recursive locking
> 
> This fixes the "INFO: possible recursive locking detected" detected by
> CONFIG_PROVE_LOCKING. The only caller to sbi_get_int_status_exit already did
> take priv->driver_lock, so don't do it again.
> 
> Signed-off-by: Holger Schurig <hs4233 at mail.mn-solutions.de>
> 
> Index: wireless-2.6/drivers/net/wireless/libertas/if_cs.c
> ===================================================================
> --- wireless-2.6.orig/drivers/net/wireless/libertas/if_cs.c	2008-01-25 13:50:20.000000000 +0100
> +++ wireless-2.6/drivers/net/wireless/libertas/if_cs.c	2008-01-25 13:50:56.000000000 +0100
> @@ -677,9 +677,7 @@ sbi_get_int_status_exit:
>  
>  	/* Card has a command result for us */
>  	if (*ireg & IF_CS_C_S_CMD_UPLD_RDY) {
> -		spin_lock(&priv->driver_lock);
>  		ret = if_cs_receive_cmdres(priv, priv->upld_buf, &priv->upld_len);
> -		spin_unlock(&priv->driver_lock);
>  		if (ret < 0)
>  			lbs_pr_err("could not receive cmd from card\n");
>  	}
> 
> 
> However, after this I still have another problem:
> 
> [ INFO: inconsistent lock state ]
> 2.6.24-rc8 #17
> 
> inconsistent {in-hardirq-W} -> {hardirq-on-W} usage.
> lbs_main/2468 [HC0[0]:SC1[1]:HE1:SE0] takes:
>  (&priv->driver_lock){+...}, at: [<f8af64c0>] lbs_thread+0x336/0x7f0 [libertas]
> {in-hardirq-W} state was registered at:
>   [<c013acc8>] __lock_acquire+0x3fd/0xbfc
>   [<c013b538>] lock_acquire+0x71/0x8b
>   [<c0348907>] _spin_lock+0x35/0x42
>   [<f88fafb6>] if_cs_interrupt+0xa9/0xcc [libertas_cs]
>   [<c0144432>] handle_IRQ_event+0x1a/0x46
>   [<c014594f>] handle_level_irq+0x7f/0xc8
>   [<c0106922>] do_IRQ+0x7c/0x96
>   [<c01049f2>] common_interrupt+0x2e/0x34
>   [<c020d64b>] acpi_idle_enter_bm+0xb3/0x2d6
>   [<c02b760d>] cpuidle_idle_call+0x5b/0x7e
>   [<c0102535>] cpu_idle+0x7a/0xab
>   [<c03461d5>] rest_init+0x5d/0x5f
>   [<c0473bdf>] start_kernel+0x2c8/0x2d0
>   [<00000000>] 0x0
>   [<ffffffff>] 0xffffffff
> irq event stamp: 819
> hardirqs last  enabled at (817): [<c0348e75>] _spin_unlock_irqrestore+0x36/0x59
> hardirqs last disabled at (818): [<c0348ac4>] _spin_lock_irq+0xf/0x48
> softirqs last  enabled at (0): [<c011ca10>] copy_process+0x4f4/0x119d
> softirqs last disabled at (819): [<c01228b9>] do_softirq+0x39/0x55
> 
> other info that might help us debug this:
> 1 lock held by lbs_main/2468:
>  #0:  (&priv->driver_lock){+...}, at: [<f8af64c0>] lbs_thread+0x336/0x7f0 [libertas]
> 
> stack backtrace:
> Pid: 2468, comm: lbs_main Not tainted 2.6.24-rc8 #17
>  [<c0104fe0>] show_trace_log_lvl+0x1a/0x2f
>  [<c0105a04>] show_trace+0x12/0x14
>  [<c010615c>] dump_stack+0x6c/0x72
>  [<c0139622>] print_usage_bug+0x140/0x14a
>  [<c013a012>] mark_lock+0x210/0x45b
>  [<c013a29e>] mark_held_locks+0x41/0x5c
>  [<c013a478>] trace_hardirqs_on+0x10b/0x14c
>  [<c01227f6>] __do_softirq+0x5b/0xe5
>  [<c01228b9>] do_softirq+0x39/0x55
>  [<c02f1fa1>] netif_rx_ni+0x35/0x58
>  [<f8afbd17>] lbs_process_rxed_packet+0x7b7/0x838 [libertas]
>  [<f88fb251>] if_cs_get_int_status+0x278/0x46f [libertas_cs]
>  [<f8af64de>] lbs_thread+0x354/0x7f0 [libertas]
>  [<c012eed8>] kthread+0x3b/0x63
>  [<c0104c2f>] kernel_thread_helper+0x7/0x10
>  =======================
> 
> What should say this to me?