Skip to content

Dwc lockdep fixes rpi 3.16.y #671

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 2 commits into from
Aug 22, 2014

Conversation

karis79
Copy link

@karis79 karis79 commented Aug 21, 2014

2 separate lockdep fixes to dwc. First one fixing false positive due to os wrapper function and second one fixing inconsistent lock state in hcd lock.

Os wrapper function for spinlock init causes lockdep to show this
false positive splat during boot:
[    3.789851] =============================================
[    3.796603] [ INFO: possible recursive locking detected ]
[    3.803320] 3.16.1+ raspberrypi#5 Not tainted
[    3.808015] ---------------------------------------------
[    3.814730] khubd/18 is trying to acquire lock:
[    3.820537]  (&(sl)->rlock){-.-...}, at: [<c0357168>] DWC_SPINLOCK_IRQSAVE+0xc/0x14
[    3.830932]
[    3.830932] but task is already holding lock:
[    3.839274]  (&(sl)->rlock){-.-...}, at: [<c0357168>] DWC_SPINLOCK_IRQSAVE+0xc/0x14
[    3.849704]
[    3.849704] other info that might help us debug this:
[    3.858826]  Possible unsafe locking scenario:
[    3.858826]
[    3.867334]        CPU0
[    3.871052]        ----
[    3.874721]   lock(&(sl)->rlock);
[    3.879302]   lock(&(sl)->rlock);
[    3.883815]
[    3.883815]  *** DEADLOCK ***
[    3.883815]
[    3.892869]  May be due to missing lock nesting notation
[    3.892869]
[    3.901736] 4 locks held by khubd/18:
[    3.906438]  #0:  (&dev->mutex){......}, at: [<c0321da8>] hub_thread+0x98/0x1000
[    3.916026]  raspberrypi#1:  (&port_dev->status_lock){+.+.+.}, at: [<c032234c>] hub_thread+0x63c/0x1000
[    3.926847]  raspberrypi#2:  (&bus->usb_address0_mutex){+.+.+.}, at: [<c031f164>] hub_port_init+0x5c/0xb24
[    3.938015]  raspberrypi#3:  (&(sl)->rlock){-.-...}, at: [<c0357168>] DWC_SPINLOCK_IRQSAVE+0xc/0x14
[    3.948730]
[    3.948730] stack backtrace:
[    3.955457] CPU: 0 PID: 18 Comm: khubd Not tainted 3.16.1+ raspberrypi#5
[    3.962541] [<c00137e4>] (unwind_backtrace) from [<c0011530>] (show_stack+0x10/0x14)
[    3.972998] [<c0011530>] (show_stack) from [<c005985c>] (__lock_acquire+0x1420/0x1ae0)
[    3.983910] [<c005985c>] (__lock_acquire) from [<c005a6c8>] (lock_acquire+0x6c/0x8c)
[    3.994908] [<c005a6c8>] (lock_acquire) from [<c04a872c>] (_raw_spin_lock_irqsave+0x50/0x64)
[    4.006756] [<c04a872c>] (_raw_spin_lock_irqsave) from [<c0357168>] (DWC_SPINLOCK_IRQSAVE+0xc/0x14)
[    4.019382] [<c0357168>] (DWC_SPINLOCK_IRQSAVE) from [<c034ba9c>] (dwc_otg_hcd_select_transactions+0x20c/0x368)
[    4.033064] [<c034ba9c>] (dwc_otg_hcd_select_transactions) from [<c034c0f8>] (dwc_otg_hcd_urb_enqueue+0x158/0x1ec)
[    4.047017] [<c034c0f8>] (dwc_otg_hcd_urb_enqueue) from [<c034d8a0>] (dwc_otg_urb_enqueue+0x1a8/0x2e0)
[    4.059889] [<c034d8a0>] (dwc_otg_urb_enqueue) from [<c03258e4>] (usb_hcd_submit_urb+0xb8/0x870)
[    4.072316] [<c03258e4>] (usb_hcd_submit_urb) from [<c03276a0>] (usb_start_wait_urb+0x44/0xbc)
[    4.084786] [<c03276a0>] (usb_start_wait_urb) from [<c03277cc>] (usb_control_msg+0xb4/0xec)
[    4.097045] [<c03277cc>] (usb_control_msg) from [<c031f528>] (hub_port_init+0x420/0xb24)
[    4.109018] [<c031f528>] (hub_port_init) from [<c0322360>] (hub_thread+0x650/0x1000)
[    4.120667] [<c0322360>] (hub_thread) from [<c003ec3c>] (kthread+0xc8/0xe4)
[    4.129668] [<c003ec3c>] (kthread) from [<c000e128>] (ret_from_fork+0x14/0x2c)

This is false positive because the lockdep uses the lock variable name
to keep track of locks. To fix this, the spin_lock_init function can't be in a
wrapper function for spinlock name to recorder correctly. I noticed similar fix
was already made for mutex debugging so used similar approach and added extra
macro to be used to spinlock allocation when spinlock debugging is on.

Signed-off-by: Kari Suvanto <[email protected]>
Lockdep gives this splat during boot:
[    4.136748] =================================
[    4.145487] [ INFO: inconsistent lock state ]
[    4.154157] 3.16.1+ raspberrypi#12 Not tainted
[    4.161852] ---------------------------------
[    4.170459] inconsistent {IN-HARDIRQ-W} -> {HARDIRQ-ON-W} usage.
[    4.180776] khubd/18 [HC0[0]:SC0[0]:HE1:SE1] takes:
[    4.189971]  (&((spinlock_t *)hcd->lock)->rlock){?.-...}, at: [<c0351490>] dwc_otg_hcd_qh_free+0x18/0xcc
[    4.204074] {IN-HARDIRQ-W} state was registered at:
[    4.213359]   [<c04a8680>] _raw_spin_lock+0x40/0x50
[    4.222743]   [<c033f010>] dwc_otg_handle_common_intr+0x44/0xd90
[    4.233133]   [<c03333c8>] dwc_otg_common_irq+0xc/0x18
[    4.242739]   [<c00634d4>] handle_irq_event_percpu+0x34/0x150
[    4.252955]   [<c006362c>] handle_irq_event+0x3c/0x5c
[    4.262395]   [<c0065984>] handle_level_irq+0x8c/0x130
[    4.271972]   [<c0062e40>] generic_handle_irq+0x28/0x40
[    4.281489]   [<c000e96c>] handle_IRQ+0x30/0x84
[    4.290442]   [<c04a9698>] __irq_svc+0x38/0xd0
[    4.299164]   [<c0357194>] DWC_MODIFY_REG32+0x64/0x84
[    4.308613]   [<c0333af4>] dwc_otg_driver_probe+0x720/0x7a8
[    4.318523]   [<c02daab0>] platform_drv_probe+0x18/0x48
[    4.328141]   [<c02d926c>] really_probe+0x68/0x200
[    4.337334]   [<c02d94f8>] __driver_attach+0xa0/0xa4
[    4.346592]   [<c02d7998>] bus_for_each_dev+0x60/0x94
[    4.355998]   [<c02d8b70>] bus_add_driver+0x140/0x1ec
[    4.365262]   [<c02d9b18>] driver_register+0x78/0xf8
[    4.374561]   [<c065e0f4>] dwc_otg_driver_init+0x58/0x114
[    4.384271]   [<c00086a4>] do_one_initcall+0x80/0x1cc
[    4.393661]   [<c0646c94>] kernel_init_freeable+0xf0/0x1b0
[    4.403501]   [<c049d83c>] kernel_init+0x8/0xec
[    4.412308]   [<c000e128>] ret_from_fork+0x14/0x2c
[    4.421444] irq event stamp: 2351
[    4.428928] hardirqs last  enabled at (2351): [<c04a89b8>] _raw_spin_unlock_irqrestore+0x7c/0x94
[    4.442100] hardirqs last disabled at (2350): [<c04a87a0>] _raw_spin_lock_irqsave+0x1c/0x64
[    4.454802] softirqs last  enabled at (2320): [<c0023b94>] __do_softirq+0x1ac/0x26c
[    4.466739] softirqs last disabled at (2297): [<c0023f80>] irq_exit+0xac/0x100
[    4.478260]
[    4.478260] other info that might help us debug this:
[    4.493215]  Possible unsafe locking scenario:
[    4.493215]
[    4.507451]        CPU0
[    4.513932]        ----
[    4.520505]   lock(&((spinlock_t *)hcd->lock)->rlock);
[    4.529767]   <Interrupt>
[    4.536515]     lock(&((spinlock_t *)hcd->lock)->rlock);
[    4.545951]
[    4.545951]  *** DEADLOCK ***
[    4.545951]
[    4.564132] 3 locks held by khubd/18:
[    4.571884]  #0:  (&dev->mutex){......}, at: [<c0321da8>] hub_thread+0x98/0x1000
[    4.583536]  raspberrypi#1:  (&port_dev->status_lock){+.+.+.}, at: [<c032234c>] hub_thread+0x63c/0x1000
[    4.596241]  raspberrypi#2:  (&bus->usb_address0_mutex){+.+.+.}, at: [<c031f164>] hub_port_init+0x5c/0xb24
[    4.609307]
[    4.609307] stack backtrace:
[    4.621705] CPU: 0 PID: 18 Comm: khubd Not tainted 3.16.1+ raspberrypi#12
[    4.631643] [<c00137e4>] (unwind_backtrace) from [<c0011530>] (show_stack+0x10/0x14)
[    4.643580] [<c0011530>] (show_stack) from [<c049f650>] (print_usage_bug+0x240/0x2b0)
[    4.655608] [<c049f650>] (print_usage_bug) from [<c0057a24>] (mark_lock+0x1d0/0x67c)
[    4.667527] [<c0057a24>] (mark_lock) from [<c0058a10>] (__lock_acquire+0x5d4/0x1ae0)
[    4.679551] [<c0058a10>] (__lock_acquire) from [<c005a6c8>] (lock_acquire+0x6c/0x8c)
[    4.691610] [<c005a6c8>] (lock_acquire) from [<c04a8680>] (_raw_spin_lock+0x40/0x50)
[    4.703584] [<c04a8680>] (_raw_spin_lock) from [<c0351490>] (dwc_otg_hcd_qh_free+0x18/0xcc)
[    4.716305] [<c0351490>] (dwc_otg_hcd_qh_free) from [<c034a60c>] (dwc_otg_hcd_endpoint_disable+0x9c/0xb0)
[    4.730246] [<c034a60c>] (dwc_otg_hcd_endpoint_disable) from [<c034d650>] (endpoint_disable+0x18/0x24)
[    4.743919] [<c034d650>] (endpoint_disable) from [<c031e0d0>] (usb_ep0_reinit+0x14/0x38)
[    4.756379] [<c031e0d0>] (usb_ep0_reinit) from [<c031f3ac>] (hub_port_init+0x2a4/0xb24)
[    4.768652] [<c031f3ac>] (hub_port_init) from [<c0322360>] (hub_thread+0x650/0x1000)
[    4.780824] [<c0322360>] (hub_thread) from [<c003ec3c>] (kthread+0xc8/0xe4)
[    4.792231] [<c003ec3c>] (kthread) from [<c000e128>] (ret_from_fork+0x14/0x2c)

This splat shows that the hcd spinlock is used from hard irq context and also from
process context with irqs on.

To fix this, use spinlock_irqsave instead of spinlock in dwc_otg_hcd_qh_free.

Signed-off-by: Kari Suvanto <[email protected]>
@popcornmix
Copy link
Collaborator

@P33M. Up to you.

P33M added a commit that referenced this pull request Aug 22, 2014
@P33M P33M merged commit 0d99826 into raspberrypi:rpi-3.16.y Aug 22, 2014
@P33M
Copy link
Contributor

P33M commented Aug 22, 2014

@karis79 thanks for ferreting this out.

pfpacket pushed a commit to pfpacket/linux-rpi-rust that referenced this pull request Apr 7, 2023
doc: rust: document how to write comments
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants