Hi Tony, does the usb(3) port still work with recent kernels?
I noticed problems with 10.4-rc5 but found that 4.9.4 is also not working while 4.8.11 works.
The symptoms/differences I see on my system are * no console log message that vbus is plugged in * no message that g_ether is configured * no usb0 in ifconfig -a * PC does not enumerate a device (even in usb2 speed)
Before I dig into our defconfig: does it work for you with recent kernels or is there a known bug/patch/workaround?
BR and thanks, Nikolaus
fixed a type in the subject...
Am 05.02.2017 um 12:31 schrieb H. Nikolaus Schaller hns@goldelico.com:
Hi Tony, does the usb(3) port still work with recent kernels?
I noticed problems with 10.4-rc5 but found that 4.9.4 is also not working while 4.8.11 works.
The symptoms/differences I see on my system are
- no console log message that vbus is plugged in
- no message that g_ether is configured
- no usb0 in ifconfig -a
- PC does not enumerate a device (even in usb2 speed)
Before I dig into our defconfig: does it work for you with recent kernels or is there a known bug/patch/workaround?
BR and thanks, Nikolaus
Kernel mailing list Kernel@pyra-handheld.com http://pyra-handheld.com/cgi-bin/mailman/listinfo/kernel
Hi,
* H. Nikolaus Schaller hns@goldelico.com [170205 03:34]:
fixed a type in the subject...
Am 05.02.2017 um 12:31 schrieb H. Nikolaus Schaller hns@goldelico.com:
Hi Tony, does the usb(3) port still work with recent kernels?
I noticed problems with 10.4-rc5 but found that 4.9.4 is also not working while 4.8.11 works.
The symptoms/differences I see on my system are
- no console log message that vbus is plugged in
- no message that g_ether is configured
- no usb0 in ifconfig -a
- PC does not enumerate a device (even in usb2 speed)
Before I dig into our defconfig: does it work for you with recent kernels or is there a known bug/patch/workaround?
Yeah so it seems, I just gave it a quick test with Linux next and nothing happens with dwc3.
Roger, do you have any ideas why dwc3 no longer works on omap5-uevm?
Regards,
Tony
Hi,
On 07/02/17 02:23, Tony Lindgren wrote:
Hi,
- H. Nikolaus Schaller hns@goldelico.com [170205 03:34]:
fixed a type in the subject...
Am 05.02.2017 um 12:31 schrieb H. Nikolaus Schaller hns@goldelico.com:
Hi Tony, does the usb(3) port still work with recent kernels?
I noticed problems with 10.4-rc5 but found that 4.9.4 is also not working while 4.8.11 works.
The symptoms/differences I see on my system are
- no console log message that vbus is plugged in
- no message that g_ether is configured
- no usb0 in ifconfig -a
- PC does not enumerate a device (even in usb2 speed)
Before I dig into our defconfig: does it work for you with recent kernels or is there a known bug/patch/workaround?
Yeah so it seems, I just gave it a quick test with Linux next and nothing happens with dwc3.
Roger, do you have any ideas why dwc3 no longer works on omap5-uevm?
I just tested it with v4.10-rc5 and linux-next-20170208. It worked fine for me using omap2plus_defconfig. Both super-speed and high-speed worked fine.
g_ether is not enabled in omap2plus_defconfig so you will have to enable it manually. CONFIG_USB_ETH=m CONFIG_USB_ETH_RNDIS=y
Are you sure you loaded g_ether? Does it show in lsmod?
cheers, -roger
Hi,
Am 08.02.2017 um 12:48 schrieb Roger Quadros rogerq@ti.com:
Hi,
On 07/02/17 02:23, Tony Lindgren wrote:
Hi,
- H. Nikolaus Schaller hns@goldelico.com [170205 03:34]:
fixed a type in the subject...
Am 05.02.2017 um 12:31 schrieb H. Nikolaus Schaller hns@goldelico.com:
Hi Tony, does the usb(3) port still work with recent kernels?
I noticed problems with 10.4-rc5 but found that 4.9.4 is also not working while 4.8.11 works.
The symptoms/differences I see on my system are
- no console log message that vbus is plugged in
- no message that g_ether is configured
- no usb0 in ifconfig -a
- PC does not enumerate a device (even in usb2 speed)
Before I dig into our defconfig: does it work for you with recent kernels or is there a known bug/patch/workaround?
Yeah so it seems, I just gave it a quick test with Linux next and nothing happens with dwc3.
Roger, do you have any ideas why dwc3 no longer works on omap5-uevm?
I just tested it with v4.10-rc5 and linux-next-20170208. It worked fine for me using omap2plus_defconfig. Both super-speed and high-speed worked fine.
g_ether is not enabled in omap2plus_defconfig so you will have to enable it manually. CONFIG_USB_ETH=m CONFIG_USB_ETH_RNDIS=y
Are you sure you loaded g_ether? Does it show in lsmod?
On my device: yes.
Maybe some u-boot dependency? I use a modified 2016.11. Should find time do more testing...
Is there a way to debug what dwc3 is doing or not doing?
BR and thanks, Nikolaus
On 11/02/17 21:57, H. Nikolaus Schaller wrote:
Hi,
Am 08.02.2017 um 12:48 schrieb Roger Quadros rogerq@ti.com:
Hi,
On 07/02/17 02:23, Tony Lindgren wrote:
Hi,
- H. Nikolaus Schaller hns@goldelico.com [170205 03:34]:
fixed a type in the subject...
Am 05.02.2017 um 12:31 schrieb H. Nikolaus Schaller hns@goldelico.com:
Hi Tony, does the usb(3) port still work with recent kernels?
I noticed problems with 10.4-rc5 but found that 4.9.4 is also not working while 4.8.11 works.
The symptoms/differences I see on my system are
- no console log message that vbus is plugged in
- no message that g_ether is configured
- no usb0 in ifconfig -a
- PC does not enumerate a device (even in usb2 speed)
Before I dig into our defconfig: does it work for you with recent kernels or is there a known bug/patch/workaround?
Yeah so it seems, I just gave it a quick test with Linux next and nothing happens with dwc3.
Roger, do you have any ideas why dwc3 no longer works on omap5-uevm?
I just tested it with v4.10-rc5 and linux-next-20170208. It worked fine for me using omap2plus_defconfig. Both super-speed and high-speed worked fine.
g_ether is not enabled in omap2plus_defconfig so you will have to enable it manually. CONFIG_USB_ETH=m CONFIG_USB_ETH_RNDIS=y
Are you sure you loaded g_ether? Does it show in lsmod?
On my device: yes.
Maybe some u-boot dependency? I use a modified 2016.11. Should find time do more testing...
Yeah. might be a good idea to try different u-boot versions.
Is there a way to debug what dwc3 is doing or not doing?
You can enable dwc3 trace events.
cd /sys/kernel/debug/tracing echo 1 > events/dwc3/enable echo 0 > events/dwc3/dwc3_readl/enable echo 0 > events/dwc3/dwc3_writel/enable echo 1 > free_buffer echo 2048 > buffer_size_kb
* Roger Quadros rogerq@ti.com [170214 01:44]:
On 11/02/17 21:57, H. Nikolaus Schaller wrote:
Hi,
Am 08.02.2017 um 12:48 schrieb Roger Quadros rogerq@ti.com:
Hi,
On 07/02/17 02:23, Tony Lindgren wrote:
Hi,
- H. Nikolaus Schaller hns@goldelico.com [170205 03:34]:
fixed a type in the subject...
Am 05.02.2017 um 12:31 schrieb H. Nikolaus Schaller hns@goldelico.com:
Hi Tony, does the usb(3) port still work with recent kernels?
I noticed problems with 10.4-rc5 but found that 4.9.4 is also not working while 4.8.11 works.
The symptoms/differences I see on my system are
- no console log message that vbus is plugged in
- no message that g_ether is configured
- no usb0 in ifconfig -a
- PC does not enumerate a device (even in usb2 speed)
Before I dig into our defconfig: does it work for you with recent kernels or is there a known bug/patch/workaround?
Yeah so it seems, I just gave it a quick test with Linux next and nothing happens with dwc3.
Roger, do you have any ideas why dwc3 no longer works on omap5-uevm?
I just tested it with v4.10-rc5 and linux-next-20170208. It worked fine for me using omap2plus_defconfig. Both super-speed and high-speed worked fine.
g_ether is not enabled in omap2plus_defconfig so you will have to enable it manually. CONFIG_USB_ETH=m CONFIG_USB_ETH_RNDIS=y
Are you sure you loaded g_ether? Does it show in lsmod?
On my device: yes.
Maybe some u-boot dependency? I use a modified 2016.11. Should find time do more testing...
Yeah. might be a good idea to try different u-boot versions.
Is there a way to debug what dwc3 is doing or not doing?
You can enable dwc3 trace events.
cd /sys/kernel/debug/tracing echo 1 > events/dwc3/enable echo 0 > events/dwc3/dwc3_readl/enable echo 0 > events/dwc3/dwc3_writel/enable echo 1 > free_buffer echo 2048 > buffer_size_kb
For me the issue was I had to change my sysfs scripts to start doing echo -n instead of just echo. Things are working for me now with Linux next.
Regards,
Tony
* Tony Lindgren tony@atomide.com [170215 13:01]:
- Roger Quadros rogerq@ti.com [170214 01:44]:
You can enable dwc3 trace events.
cd /sys/kernel/debug/tracing echo 1 > events/dwc3/enable echo 0 > events/dwc3/dwc3_readl/enable echo 0 > events/dwc3/dwc3_writel/enable echo 1 > free_buffer echo 2048 > buffer_size_kb
For me the issue was I had to change my sysfs scripts to start doing echo -n instead of just echo. Things are working for me now with Linux next.
Then in host mode after connecting a device, I see the following warnings with Linux next and lockdep enabled if host mode is forced with dr_mode = "host":
CONFIG_DEBUG_LOCKDEP=y CONFIG_DEBUG_ATOMIC_SLEEP=y
Regards,
Tony
8< -------------------------------- [ 48.431095] BUG: sleeping function called from invalid context at kernel/locking/mutex.c:745 [ 48.439609] in_atomic(): 1, irqs_disabled(): 128, pid: 416, name: kworker/1:2 [ 48.446774] 3 locks held by kworker/1:2/416: [ 48.451058] #0: ("events_power_efficient"){.+.+.+}, at: [<c01565b0>] process_one_work+0x1f8/0x808 [ 48.460168] #1: ((&(&palmas_usb->wq_detectid)->work)){+.+...}, at: [<c01565b0>] process_one_work+0x1f8/0x808 [ 48.470226] #2: (&(&edev->lock)->rlock){......}, at: [<bf028324>] extcon_sync+0x70/0x1c8 [extcon_core] [ 48.479770] irq event stamp: 7468 [ 48.483102] hardirqs last enabled at (7467): [<c083a970>] _raw_spin_unlock_irqrestore+0x30/0x5c [ 48.491925] hardirqs last disabled at (7468): [<c083a7bc>] _raw_spin_lock_irqsave+0x1c/0x64 [ 48.500315] softirqs last enabled at (5354): [<c01f0b2c>] css_release_work_fn+0xf4/0x264 [ 48.508528] softirqs last disabled at (5352): [<c01f0b14>] css_release_work_fn+0xdc/0x264 [ 48.516741] CPU: 1 PID: 416 Comm: kworker/1:2 Not tainted 4.10.0-rc8-next-20170215+ #123 [ 48.524864] Hardware name: Generic OMAP5 (Flattened Device Tree) [ 48.530898] Workqueue: events_power_efficient palmas_gpio_id_detect [extcon_palmas] [ 48.538597] [<c0110228>] (unwind_backtrace) from [<c010c224>] (show_stack+0x10/0x14) [ 48.546379] [<c010c224>] (show_stack) from [<c04ca860>] (dump_stack+0xac/0xe0) [ 48.553637] [<c04ca860>] (dump_stack) from [<c0165fa0>] (___might_sleep+0x17c/0x2a4) [ 48.561416] [<c0165fa0>] (___might_sleep) from [<c0835fec>] (__mutex_lock+0x28/0x9f8) [ 48.569281] [<c0835fec>] (__mutex_lock) from [<c08369d8>] (mutex_lock_nested+0x1c/0x24) [ 48.577322] [<c08369d8>] (mutex_lock_nested) from [<c05478dc>] (regulator_enable+0x40/0x1dc) [ 48.585803] [<c05478dc>] (regulator_enable) from [<bf29d32c>] (dwc3_omap_set_mailbox+0xcc/0x184 [dwc3_omap]) [ 48.595705] [<bf29d32c>] (dwc3_omap_set_mailbox [dwc3_omap]) from [<bf29d7ec>] (dwc3_omap_id_notifier+0x14/0x1c [dwc3_omap]) [ 48.606979] [<bf29d7ec>] (dwc3_omap_id_notifier [dwc3_omap]) from [<c015f3ac>] (notifier_call_chain+0x44/0x80) [ 48.617028] [<c015f3ac>] (notifier_call_chain) from [<c015f520>] (raw_notifier_call_chain+0x18/0x20) [ 48.626209] [<c015f520>] (raw_notifier_call_chain) from [<bf028344>] (extcon_sync+0x90/0x1c8 [extcon_core]) [ 48.636004] [<bf028344>] (extcon_sync [extcon_core]) from [<c015666c>] (process_one_work+0x2b4/0x808) [ 48.645268] [<c015666c>] (process_one_work) from [<c0157794>] (worker_thread+0x3c/0x550) [ 48.653396] [<c0157794>] (worker_thread) from [<c015d664>] (kthread+0x104/0x148) [ 48.660828] [<c015d664>] (kthread) from [<c0107830>] (ret_from_fork+0x14/0x24) [ 48.668313] BUG: scheduling while atomic: kworker/1:2/416/0x00000002 [ 48.674717] 5 locks held by kworker/1:2/416: [ 48.679003] #0: ("events_power_efficient"){.+.+.+}, at: [<c01565b0>] process_one_work+0x1f8/0x808 [ 48.688140] #1: ((&(&palmas_usb->wq_detectid)->work)){+.+...}, at: [<c01565b0>] process_one_work+0x1f8/0x808 [ 48.698231] #2: (&(&edev->lock)->rlock){+.+...}, at: [<bf028324>] extcon_sync+0x70/0x1c8 [extcon_core] [ 48.707807] #3: (&rdev->mutex){+.+.+.}, at: [<c05478dc>] regulator_enable+0x40/0x1dc [ 48.715803] #4: (palmas:546:(&palmas_regmap_config[i])->lock){+.+.+.}, at: [<c05aa170>] regmap_read+0x2c/0x5c [ 48.725983] Modules linked in: usb_f_ecm usb_storage cppi41 am35x musb_dsps musb_am335x omap2430 phy_cpcap_usb phy_dm816x_usb phy_am335x phy_am335x_control phy_twl6030_usb phy_twl4030_usb musb_hdrc mwifiex_sdio mwifiex arc4 wlcore_sdio wl18xx wl12xx wlcore mac80211 cfg80211 omapdrm drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops drm panel_dsi_cm lm3532_bl atmel_mxt_ts omap4_keypad matrix_keymap evdev ti_lmu_backlight ti_lmu connector_hdmi omapdss cfbimgblt cfbfillrect cfbcopyarea gpio_pca953x hid_generic usbhid smsc95xx smsc75xx usbnet usb_f_acm u_ether usb_f_mass_storage usb_f_serial u_serial xhci_plat_hcd xhci_hcd dwc3_omap dwc3 ohci_omap3 ohci_hcd ehci_omap ehci_hcd phy_omap_usb2 phy_generic libcomposite udc_core snd_soc_simple_card snd_soc_simple_card_utils snd_usb_audio snd_usbmidi_lib [ 48.797725] usbcore usb_common snd_soc_omap_mcbsp snd_soc_omap_dmic snd_soc_omap_twl4030 snd_soc_omap_abe_twl6040 snd_soc_omap_mcpdm snd_soc_twl6040 snd_soc_twl4030 snd_soc_omap snd_soc_core snd_hwdep snd_pcm_dmaengine snd_pcm snd_timer snd_rawmidi snd soundcore rtc_ds1307 hwmon rtc_palmas rtc_twl palmas_pwrbutton extcon_palmas extcon_core ti_soc_thermal clk_palmas lib80211 ccm [ 48.831540] CPU: 1 PID: 416 Comm: kworker/1:2 Tainted: G W 4.10.0-rc8-next-20170215+ #123 [ 48.840892] Hardware name: Generic OMAP5 (Flattened Device Tree) [ 48.846926] Workqueue: events_power_efficient palmas_gpio_id_detect [extcon_palmas] [ 48.854623] [<c0110228>] (unwind_backtrace) from [<c010c224>] (show_stack+0x10/0x14) [ 48.862403] [<c010c224>] (show_stack) from [<c04ca860>] (dump_stack+0xac/0xe0) [ 48.869661] [<c04ca860>] (dump_stack) from [<c0165dec>] (__schedule_bug+0x6c/0xa4) [ 48.877270] [<c0165dec>] (__schedule_bug) from [<c0834820>] (__schedule+0xa38/0xe84) [ 48.885051] [<c0834820>] (__schedule) from [<c0834cc0>] (schedule+0x54/0xb8) [ 48.892133] [<c0834cc0>] (schedule) from [<c0839b98>] (schedule_timeout+0x23c/0x4a0) [ 48.899921] [<c0839b98>] (schedule_timeout) from [<c08357b4>] (wait_for_common+0xa8/0x164) [ 48.908230] [<c08357b4>] (wait_for_common) from [<c066c6e0>] (omap_i2c_xfer+0x3d8/0x550) [ 48.916356] [<c066c6e0>] (omap_i2c_xfer) from [<c0667f14>] (__i2c_transfer+0x13c/0x9d8) [ 48.924396] [<c0667f14>] (__i2c_transfer) from [<c0668820>] (i2c_transfer+0x70/0xb4) [ 48.932175] [<c0668820>] (i2c_transfer) from [<c05b0f7c>] (regmap_i2c_read+0x48/0x64) [ 48.940048] [<c05b0f7c>] (regmap_i2c_read) from [<c05aabd4>] (_regmap_raw_read+0xe4/0x488) [ 48.948350] [<c05aabd4>] (_regmap_raw_read) from [<c05aaf9c>] (_regmap_bus_read+0x24/0x4c) [ 48.956651] [<c05aaf9c>] (_regmap_bus_read) from [<c05a9f3c>] (_regmap_read+0x64/0x26c) [ 48.964690] [<c05a9f3c>] (_regmap_read) from [<c05aa180>] (regmap_read+0x3c/0x5c) [ 48.972207] [<c05aa180>] (regmap_read) from [<c05490c8>] (regulator_is_enabled_regmap+0x20/0x9c) [ 48.981033] [<c05490c8>] (regulator_is_enabled_regmap) from [<c05479f4>] (regulator_enable+0x158/0x1dc) [ 48.990472] [<c05479f4>] (regulator_enable) from [<bf29d32c>] (dwc3_omap_set_mailbox+0xcc/0x184 [dwc3_omap]) [ 49.000387] [<bf29d32c>] (dwc3_omap_set_mailbox [dwc3_omap]) from [<bf29d7ec>] (dwc3_omap_id_notifier+0x14/0x1c [dwc3_omap]) [ 49.011661] [<bf29d7ec>] (dwc3_omap_id_notifier [dwc3_omap]) from [<c015f3ac>] (notifier_call_chain+0x44/0x80) [ 49.021710] [<c015f3ac>] (notifier_call_chain) from [<c015f520>] (raw_notifier_call_chain+0x18/0x20) [ 49.030892] [<c015f520>] (raw_notifier_call_chain) from [<bf028344>] (extcon_sync+0x90/0x1c8 [extcon_core]) [ 49.040688] [<bf028344>] (extcon_sync [extcon_core]) from [<c015666c>] (process_one_work+0x2b4/0x808) [ 49.049952] [<c015666c>] (process_one_work) from [<c0157794>] (worker_thread+0x3c/0x550) [ 49.058080] [<c0157794>] (worker_thread) from [<c015d664>] (kthread+0x104/0x148) [ 49.065509] [<c015d664>] (kthread) from [<c0107830>] (ret_from_fork+0x14/0x24)
[ 49.075275] =============================== [ 49.079503] [ ERR: suspicious RCU usage. ] [ 49.083774] 4.10.0-rc8-next-20170215+ #123 Tainted: G W [ 49.090211] ------------------------------- [ 49.094454] ./include/trace/events/kmem.h:51 suspicious rcu_dereference_check() usage! [ 49.102470] other info that might help us debug this:
[ 49.110581] rcu_scheduler_active = 2, debug_locks = 0 [ 49.117181] 2 locks held by kworker/1:2/416: [ 49.121551] #0: ("events_power_efficient"){.+.+.+}, at: [<c01565b0>] process_one_work+0x1f8/0x808 [ 49.130715] #1: ((&(&palmas_usb->wq_detectid)->work)){+.+.+.}, at: [<c01565b0>] process_one_work+0x1f8/0x808 [ 49.140845] stack backtrace: [ 49.145264] CPU: 1 PID: 416 Comm: kworker/1:2 Tainted: G W 4.10.0-rc8-next-20170215+ #123 [ 49.154614] Hardware name: Generic OMAP5 (Flattened Device Tree) [ 49.160649] Workqueue: events_power_efficient palmas_gpio_id_detect [extcon_palmas] [ 49.168345] [<c0110228>] (unwind_backtrace) from [<c010c224>] (show_stack+0x10/0x14) [ 49.176123] [<c010c224>] (show_stack) from [<c04ca860>] (dump_stack+0xac/0xe0) [ 49.183385] [<c04ca860>] (dump_stack) from [<c02aa500>] (kmem_cache_alloc_trace+0x2fc/0x364) [ 49.191865] [<c02aa500>] (kmem_cache_alloc_trace) from [<c04cd05c>] (kobject_uevent_env+0xac/0x4f4) [ 49.200959] [<c04cd05c>] (kobject_uevent_env) from [<bf028424>] (extcon_sync+0x170/0x1c8 [extcon_core]) [ 49.210403] [<bf028424>] (extcon_sync [extcon_core]) from [<c015666c>] (process_one_work+0x2b4/0x808) [ 49.219666] [<c015666c>] (process_one_work) from [<c0157794>] (worker_thread+0x3c/0x550) [ 49.227794] [<c0157794>] (worker_thread) from [<c015d664>] (kthread+0x104/0x148) [ 49.235225] [<c015d664>] (kthread) from [<c0107830>] (ret_from_fork+0x14/0x24) [ 49.242589] BUG: workqueue leaked lock or atomic: kworker/1:2/0xffffffff/416 last function: palmas_gpio_id_detect [extcon_palmas] [ 49.256144] INFO: lockdep is turned off. [ 49.260099] CPU: 1 PID: 416 Comm: kworker/1:2 Tainted: G W 4.10.0-rc8-next-20170215+ #123 [ 49.269442] Hardware name: Generic OMAP5 (Flattened Device Tree) [ 49.275477] Workqueue: events_power_efficient palmas_gpio_id_detect [extcon_palmas] [ 49.283174] [<c0110228>] (unwind_backtrace) from [<c010c224>] (show_stack+0x10/0x14) [ 49.290953] [<c010c224>] (show_stack) from [<c04ca860>] (dump_stack+0xac/0xe0) [ 49.298210] [<c04ca860>] (dump_stack) from [<c0156998>] (process_one_work+0x5e0/0x808) [ 49.306165] [<c0156998>] (process_one_work) from [<c0157794>] (worker_thread+0x3c/0x550) [ 49.314293] [<c0157794>] (worker_thread) from [<c015d664>] (kthread+0x104/0x148) [ 49.321723] [<c015d664>] (kthread) from [<c0107830>] (ret_from_fork+0x14/0x24) [ 49.328998] BUG: scheduling while atomic: kworker/1:2/416/0x00000000 [ 49.335450] INFO: lockdep is turned off. [ 49.339433] Modules linked in: usb_f_ecm usb_storage cppi41 am35x musb_dsps musb_am335x omap2430 phy_cpcap_usb phy_dm816x_usb phy_am335x phy_am335x_control phy_twl6030_usb phy_twl4030_usb musb_hdrc mwifiex_sdio mwifiex arc4 wlcore_sdio wl18xx wl12xx wlcore mac80211 cfg80211 omapdrm drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops drm panel_dsi_cm lm3532_bl atmel_mxt_ts omap4_keypad matrix_keymap evdev ti_lmu_backlight ti_lmu connector_hdmi omapdss cfbimgblt cfbfillrect cfbcopyarea gpio_pca953x hid_generic usbhid smsc95xx smsc75xx usbnet usb_f_acm u_ether usb_f_mass_storage usb_f_serial u_serial xhci_plat_hcd xhci_hcd dwc3_omap dwc3 ohci_omap3 ohci_hcd ehci_omap ehci_hcd phy_omap_usb2 phy_generic libcomposite udc_core snd_soc_simple_card snd_soc_simple_card_utils snd_usb_audio snd_usbmidi_lib [ 49.339938] usb 3-1: new high-speed USB device number 2 using xhci-hcd [ 49.417777] usbcore usb_common snd_soc_omap_mcbsp snd_soc_omap_dmic snd_soc_omap_twl4030 snd_soc_omap_abe_twl6040 snd_soc_omap_mcpdm snd_soc_twl6040 snd_soc_twl4030 snd_soc_omap snd_soc_core snd_hwdep snd_pcm_dmaengine snd_pcm snd_timer snd_rawmidi snd soundcore rtc_ds1307 hwmon rtc_palmas rtc_twl palmas_pwrbutton extcon_palmas extcon_core ti_soc_thermal clk_palmas lib80211 ccm [ 49.451601] CPU: 1 PID: 416 Comm: kworker/1:2 Tainted: G W 4.10.0-rc8-next-20170215+ #123 [ 49.460944] Hardware name: Generic OMAP5 (Flattened Device Tree) [ 49.466986] [<c0110228>] (unwind_backtrace) from [<c010c224>] (show_stack+0x10/0x14) [ 49.474764] [<c010c224>] (show_stack) from [<c04ca860>] (dump_stack+0xac/0xe0) [ 49.482021] [<c04ca860>] (dump_stack) from [<c0165dec>] (__schedule_bug+0x6c/0xa4) [ 49.489628] [<c0165dec>] (__schedule_bug) from [<c0834820>] (__schedule+0xa38/0xe84) [ 49.497408] [<c0834820>] (__schedule) from [<c0834cc0>] (schedule+0x54/0xb8) [ 49.504491] [<c0834cc0>] (schedule) from [<c015780c>] (worker_thread+0xb4/0x550) [ 49.511921] [<c015780c>] (worker_thread) from [<c015d664>] (kthread+0x104/0x148) [ 49.519351] [<c015d664>] (kthread) from [<c0107830>] (ret_from_fork+0x14/0x24) [ 49.563684] usb 3-1: New USB device found, idVendor=05e3, idProduct=0745 [ 49.570522] usb 3-1: New USB device strings: Mfr=0, Product=1, SerialNumber=2 [ 49.577684] usb 3-1: Product: USB Storage [ 49.581887] usb 3-1: SerialNumber: 000000000902 [ 49.587894] usb-storage 3-1:1.0: USB Mass Storage device detected [ 49.596532] scsi host1: usb-storage 3-1:1.0 [ 49.601738] of_get_named_gpiod_flags: can't parse 'hpd-gpios' property of node '/connector[0]' [ 49.610869] connector-hdmi connector: failed to find video source [ 50.661720] scsi 1:0:0:0: Direct-Access Generic STORAGE DEVICE 0902 PQ: 0 ANSI: 6 [ 50.672125] of_get_named_gpiod_flags: can't parse 'hpd-gpios' property of node '/connector[0]' [ 50.681001] connector-hdmi connector: failed to find video source [ 50.918830] sd 1:0:0:0: [sda] 7882752 512-byte logical blocks: (4.04 GB/3.76 GiB) [ 50.927672] sd 1:0:0:0: [sda] Write Protect is off [ 50.932539] sd 1:0:0:0: [sda] Mode Sense: 21 00 00 00 [ 50.938860] sd 1:0:0:0: [sda] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA [ 50.954522] sda: sda1 [ 50.960682] sd 1:0:0:0: [sda] Attached SCSI removable disk
+Chanwoo
On 15/02/17 23:36, Tony Lindgren wrote:
- Tony Lindgren tony@atomide.com [170215 13:01]:
- Roger Quadros rogerq@ti.com [170214 01:44]:
You can enable dwc3 trace events.
cd /sys/kernel/debug/tracing echo 1 > events/dwc3/enable echo 0 > events/dwc3/dwc3_readl/enable echo 0 > events/dwc3/dwc3_writel/enable echo 1 > free_buffer echo 2048 > buffer_size_kb
For me the issue was I had to change my sysfs scripts to start doing echo -n instead of just echo. Things are working for me now with Linux next.
Then in host mode after connecting a device, I see the following warnings with Linux next and lockdep enabled if host mode is forced with dr_mode = "host":
CONFIG_DEBUG_LOCKDEP=y CONFIG_DEBUG_ATOMIC_SLEEP=y
Looks like extcon is calling the notifiers while atomic. (spinlocks held, IRQs disabled?) Does this needs to be fixed at extcon layer or dwc3-omap should execute the mailbox in a workqueue?
cheers, -roger
Regards,
Tony
8< -------------------------------- [ 48.431095] BUG: sleeping function called from invalid context at kernel/locking/mutex.c:745 [ 48.439609] in_atomic(): 1, irqs_disabled(): 128, pid: 416, name: kworker/1:2 [ 48.446774] 3 locks held by kworker/1:2/416: [ 48.451058] #0: ("events_power_efficient"){.+.+.+}, at: [<c01565b0>] process_one_work+0x1f8/0x808 [ 48.460168] #1: ((&(&palmas_usb->wq_detectid)->work)){+.+...}, at: [<c01565b0>] process_one_work+0x1f8/0x808 [ 48.470226] #2: (&(&edev->lock)->rlock){......}, at: [<bf028324>] extcon_sync+0x70/0x1c8 [extcon_core] [ 48.479770] irq event stamp: 7468 [ 48.483102] hardirqs last enabled at (7467): [<c083a970>] _raw_spin_unlock_irqrestore+0x30/0x5c [ 48.491925] hardirqs last disabled at (7468): [<c083a7bc>] _raw_spin_lock_irqsave+0x1c/0x64 [ 48.500315] softirqs last enabled at (5354): [<c01f0b2c>] css_release_work_fn+0xf4/0x264 [ 48.508528] softirqs last disabled at (5352): [<c01f0b14>] css_release_work_fn+0xdc/0x264 [ 48.516741] CPU: 1 PID: 416 Comm: kworker/1:2 Not tainted 4.10.0-rc8-next-20170215+ #123 [ 48.524864] Hardware name: Generic OMAP5 (Flattened Device Tree) [ 48.530898] Workqueue: events_power_efficient palmas_gpio_id_detect [extcon_palmas] [ 48.538597] [<c0110228>] (unwind_backtrace) from [<c010c224>] (show_stack+0x10/0x14) [ 48.546379] [<c010c224>] (show_stack) from [<c04ca860>] (dump_stack+0xac/0xe0) [ 48.553637] [<c04ca860>] (dump_stack) from [<c0165fa0>] (___might_sleep+0x17c/0x2a4) [ 48.561416] [<c0165fa0>] (___might_sleep) from [<c0835fec>] (__mutex_lock+0x28/0x9f8) [ 48.569281] [<c0835fec>] (__mutex_lock) from [<c08369d8>] (mutex_lock_nested+0x1c/0x24) [ 48.577322] [<c08369d8>] (mutex_lock_nested) from [<c05478dc>] (regulator_enable+0x40/0x1dc) [ 48.585803] [<c05478dc>] (regulator_enable) from [<bf29d32c>] (dwc3_omap_set_mailbox+0xcc/0x184 [dwc3_omap]) [ 48.595705] [<bf29d32c>] (dwc3_omap_set_mailbox [dwc3_omap]) from [<bf29d7ec>] (dwc3_omap_id_notifier+0x14/0x1c [dwc3_omap]) [ 48.606979] [<bf29d7ec>] (dwc3_omap_id_notifier [dwc3_omap]) from [<c015f3ac>] (notifier_call_chain+0x44/0x80) [ 48.617028] [<c015f3ac>] (notifier_call_chain) from [<c015f520>] (raw_notifier_call_chain+0x18/0x20) [ 48.626209] [<c015f520>] (raw_notifier_call_chain) from [<bf028344>] (extcon_sync+0x90/0x1c8 [extcon_core]) [ 48.636004] [<bf028344>] (extcon_sync [extcon_core]) from [<c015666c>] (process_one_work+0x2b4/0x808) [ 48.645268] [<c015666c>] (process_one_work) from [<c0157794>] (worker_thread+0x3c/0x550) [ 48.653396] [<c0157794>] (worker_thread) from [<c015d664>] (kthread+0x104/0x148) [ 48.660828] [<c015d664>] (kthread) from [<c0107830>] (ret_from_fork+0x14/0x24) [ 48.668313] BUG: scheduling while atomic: kworker/1:2/416/0x00000002 [ 48.674717] 5 locks held by kworker/1:2/416: [ 48.679003] #0: ("events_power_efficient"){.+.+.+}, at: [<c01565b0>] process_one_work+0x1f8/0x808 [ 48.688140] #1: ((&(&palmas_usb->wq_detectid)->work)){+.+...}, at: [<c01565b0>] process_one_work+0x1f8/0x808 [ 48.698231] #2: (&(&edev->lock)->rlock){+.+...}, at: [<bf028324>] extcon_sync+0x70/0x1c8 [extcon_core] [ 48.707807] #3: (&rdev->mutex){+.+.+.}, at: [<c05478dc>] regulator_enable+0x40/0x1dc [ 48.715803] #4: (palmas:546:(&palmas_regmap_config[i])->lock){+.+.+.}, at: [<c05aa170>] regmap_read+0x2c/0x5c [ 48.725983] Modules linked in: usb_f_ecm usb_storage cppi41 am35x musb_dsps musb_am335x omap2430 phy_cpcap_usb phy_dm816x_usb phy_am335x phy_am335x_control phy_twl6030_usb phy_twl4030_usb musb_hdrc mwifiex_sdio mwifiex arc4 wlcore_sdio wl18xx wl12xx wlcore mac80211 cfg80211 omapdrm drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops drm panel_dsi_cm lm3532_bl atmel_mxt_ts omap4_keypad matrix_keymap evdev ti_lmu_backlight ti_lmu connector_hdmi omapdss cfbimgblt cfbfillrect cfbcopyarea gpio_pca953x hid_generic usbhid smsc95xx smsc75xx usbnet usb_f_acm u_ether usb_f_mass_storage usb_f_serial u_serial xhci_plat_hcd xhci_hcd dwc3_omap dwc3 ohci_omap3 ohci_hcd ehci_omap ehci_hcd phy_omap_usb2 phy_generic libcomposite udc_core snd_soc_simple_card snd_soc_simple_card_utils snd_usb_audio snd_usbmidi_lib [ 48.797725] usbcore usb_common snd_soc_omap_mcbsp snd_soc_omap_dmic snd_soc_omap_twl4030 snd_soc_omap_abe_twl6040 snd_soc_omap_mcpdm snd_soc_twl6040 snd_soc_twl4030 snd_soc_omap snd_soc_core snd_hwdep snd_pcm_dmaengine snd_pcm snd_timer snd_rawmidi snd soundcore rtc_ds1307 hwmon rtc_palmas rtc_twl palmas_pwrbutton extcon_palmas extcon_core ti_soc_thermal clk_palmas lib80211 ccm [ 48.831540] CPU: 1 PID: 416 Comm: kworker/1:2 Tainted: G W 4.10.0-rc8-next-20170215+ #123 [ 48.840892] Hardware name: Generic OMAP5 (Flattened Device Tree) [ 48.846926] Workqueue: events_power_efficient palmas_gpio_id_detect [extcon_palmas] [ 48.854623] [<c0110228>] (unwind_backtrace) from [<c010c224>] (show_stack+0x10/0x14) [ 48.862403] [<c010c224>] (show_stack) from [<c04ca860>] (dump_stack+0xac/0xe0) [ 48.869661] [<c04ca860>] (dump_stack) from [<c0165dec>] (__schedule_bug+0x6c/0xa4) [ 48.877270] [<c0165dec>] (__schedule_bug) from [<c0834820>] (__schedule+0xa38/0xe84) [ 48.885051] [<c0834820>] (__schedule) from [<c0834cc0>] (schedule+0x54/0xb8) [ 48.892133] [<c0834cc0>] (schedule) from [<c0839b98>] (schedule_timeout+0x23c/0x4a0) [ 48.899921] [<c0839b98>] (schedule_timeout) from [<c08357b4>] (wait_for_common+0xa8/0x164) [ 48.908230] [<c08357b4>] (wait_for_common) from [<c066c6e0>] (omap_i2c_xfer+0x3d8/0x550) [ 48.916356] [<c066c6e0>] (omap_i2c_xfer) from [<c0667f14>] (__i2c_transfer+0x13c/0x9d8) [ 48.924396] [<c0667f14>] (__i2c_transfer) from [<c0668820>] (i2c_transfer+0x70/0xb4) [ 48.932175] [<c0668820>] (i2c_transfer) from [<c05b0f7c>] (regmap_i2c_read+0x48/0x64) [ 48.940048] [<c05b0f7c>] (regmap_i2c_read) from [<c05aabd4>] (_regmap_raw_read+0xe4/0x488) [ 48.948350] [<c05aabd4>] (_regmap_raw_read) from [<c05aaf9c>] (_regmap_bus_read+0x24/0x4c) [ 48.956651] [<c05aaf9c>] (_regmap_bus_read) from [<c05a9f3c>] (_regmap_read+0x64/0x26c) [ 48.964690] [<c05a9f3c>] (_regmap_read) from [<c05aa180>] (regmap_read+0x3c/0x5c) [ 48.972207] [<c05aa180>] (regmap_read) from [<c05490c8>] (regulator_is_enabled_regmap+0x20/0x9c) [ 48.981033] [<c05490c8>] (regulator_is_enabled_regmap) from [<c05479f4>] (regulator_enable+0x158/0x1dc) [ 48.990472] [<c05479f4>] (regulator_enable) from [<bf29d32c>] (dwc3_omap_set_mailbox+0xcc/0x184 [dwc3_omap]) [ 49.000387] [<bf29d32c>] (dwc3_omap_set_mailbox [dwc3_omap]) from [<bf29d7ec>] (dwc3_omap_id_notifier+0x14/0x1c [dwc3_omap]) [ 49.011661] [<bf29d7ec>] (dwc3_omap_id_notifier [dwc3_omap]) from [<c015f3ac>] (notifier_call_chain+0x44/0x80) [ 49.021710] [<c015f3ac>] (notifier_call_chain) from [<c015f520>] (raw_notifier_call_chain+0x18/0x20) [ 49.030892] [<c015f520>] (raw_notifier_call_chain) from [<bf028344>] (extcon_sync+0x90/0x1c8 [extcon_core]) [ 49.040688] [<bf028344>] (extcon_sync [extcon_core]) from [<c015666c>] (process_one_work+0x2b4/0x808) [ 49.049952] [<c015666c>] (process_one_work) from [<c0157794>] (worker_thread+0x3c/0x550) [ 49.058080] [<c0157794>] (worker_thread) from [<c015d664>] (kthread+0x104/0x148) [ 49.065509] [<c015d664>] (kthread) from [<c0107830>] (ret_from_fork+0x14/0x24)
[ 49.075275] =============================== [ 49.079503] [ ERR: suspicious RCU usage. ] [ 49.083774] 4.10.0-rc8-next-20170215+ #123 Tainted: G W [ 49.090211] ------------------------------- [ 49.094454] ./include/trace/events/kmem.h:51 suspicious rcu_dereference_check() usage! [ 49.102470] other info that might help us debug this:
[ 49.110581] rcu_scheduler_active = 2, debug_locks = 0 [ 49.117181] 2 locks held by kworker/1:2/416: [ 49.121551] #0: ("events_power_efficient"){.+.+.+}, at: [<c01565b0>] process_one_work+0x1f8/0x808 [ 49.130715] #1: ((&(&palmas_usb->wq_detectid)->work)){+.+.+.}, at: [<c01565b0>] process_one_work+0x1f8/0x808 [ 49.140845] stack backtrace: [ 49.145264] CPU: 1 PID: 416 Comm: kworker/1:2 Tainted: G W 4.10.0-rc8-next-20170215+ #123 [ 49.154614] Hardware name: Generic OMAP5 (Flattened Device Tree) [ 49.160649] Workqueue: events_power_efficient palmas_gpio_id_detect [extcon_palmas] [ 49.168345] [<c0110228>] (unwind_backtrace) from [<c010c224>] (show_stack+0x10/0x14) [ 49.176123] [<c010c224>] (show_stack) from [<c04ca860>] (dump_stack+0xac/0xe0) [ 49.183385] [<c04ca860>] (dump_stack) from [<c02aa500>] (kmem_cache_alloc_trace+0x2fc/0x364) [ 49.191865] [<c02aa500>] (kmem_cache_alloc_trace) from [<c04cd05c>] (kobject_uevent_env+0xac/0x4f4) [ 49.200959] [<c04cd05c>] (kobject_uevent_env) from [<bf028424>] (extcon_sync+0x170/0x1c8 [extcon_core]) [ 49.210403] [<bf028424>] (extcon_sync [extcon_core]) from [<c015666c>] (process_one_work+0x2b4/0x808) [ 49.219666] [<c015666c>] (process_one_work) from [<c0157794>] (worker_thread+0x3c/0x550) [ 49.227794] [<c0157794>] (worker_thread) from [<c015d664>] (kthread+0x104/0x148) [ 49.235225] [<c015d664>] (kthread) from [<c0107830>] (ret_from_fork+0x14/0x24) [ 49.242589] BUG: workqueue leaked lock or atomic: kworker/1:2/0xffffffff/416 last function: palmas_gpio_id_detect [extcon_palmas] [ 49.256144] INFO: lockdep is turned off. [ 49.260099] CPU: 1 PID: 416 Comm: kworker/1:2 Tainted: G W 4.10.0-rc8-next-20170215+ #123 [ 49.269442] Hardware name: Generic OMAP5 (Flattened Device Tree) [ 49.275477] Workqueue: events_power_efficient palmas_gpio_id_detect [extcon_palmas] [ 49.283174] [<c0110228>] (unwind_backtrace) from [<c010c224>] (show_stack+0x10/0x14) [ 49.290953] [<c010c224>] (show_stack) from [<c04ca860>] (dump_stack+0xac/0xe0) [ 49.298210] [<c04ca860>] (dump_stack) from [<c0156998>] (process_one_work+0x5e0/0x808) [ 49.306165] [<c0156998>] (process_one_work) from [<c0157794>] (worker_thread+0x3c/0x550) [ 49.314293] [<c0157794>] (worker_thread) from [<c015d664>] (kthread+0x104/0x148) [ 49.321723] [<c015d664>] (kthread) from [<c0107830>] (ret_from_fork+0x14/0x24) [ 49.328998] BUG: scheduling while atomic: kworker/1:2/416/0x00000000 [ 49.335450] INFO: lockdep is turned off. [ 49.339433] Modules linked in: usb_f_ecm usb_storage cppi41 am35x musb_dsps musb_am335x omap2430 phy_cpcap_usb phy_dm816x_usb phy_am335x phy_am335x_control phy_twl6030_usb phy_twl4030_usb musb_hdrc mwifiex_sdio mwifiex arc4 wlcore_sdio wl18xx wl12xx wlcore mac80211 cfg80211 omapdrm drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops drm panel_dsi_cm lm3532_bl atmel_mxt_ts omap4_keypad matrix_keymap evdev ti_lmu_backlight ti_lmu connector_hdmi omapdss cfbimgblt cfbfillrect cfbcopyarea gpio_pca953x hid_generic usbhid smsc95xx smsc75xx usbnet usb_f_acm u_ether usb_f_mass_storage usb_f_serial u_serial xhci_plat_hcd xhci_hcd dwc3_omap dwc3 ohci_omap3 ohci_hcd ehci_omap ehci_hcd phy_omap_usb2 phy_generic libcomposite udc_core snd_soc_simple_card snd_soc_simple_card_utils snd_usb_audio snd_usbmidi_lib [ 49.339938] usb 3-1: new high-speed USB device number 2 using xhci-hcd [ 49.417777] usbcore usb_common snd_soc_omap_mcbsp snd_soc_omap_dmic snd_soc_omap_twl4030 snd_soc_omap_abe_twl6040 snd_soc_omap_mcpdm snd_soc_twl6040 snd_soc_twl4030 snd_soc_omap snd_soc_core snd_hwdep snd_pcm_dmaengine snd_pcm snd_timer snd_rawmidi snd soundcore rtc_ds1307 hwmon rtc_palmas rtc_twl palmas_pwrbutton extcon_palmas extcon_core ti_soc_thermal clk_palmas lib80211 ccm [ 49.451601] CPU: 1 PID: 416 Comm: kworker/1:2 Tainted: G W 4.10.0-rc8-next-20170215+ #123 [ 49.460944] Hardware name: Generic OMAP5 (Flattened Device Tree) [ 49.466986] [<c0110228>] (unwind_backtrace) from [<c010c224>] (show_stack+0x10/0x14) [ 49.474764] [<c010c224>] (show_stack) from [<c04ca860>] (dump_stack+0xac/0xe0) [ 49.482021] [<c04ca860>] (dump_stack) from [<c0165dec>] (__schedule_bug+0x6c/0xa4) [ 49.489628] [<c0165dec>] (__schedule_bug) from [<c0834820>] (__schedule+0xa38/0xe84) [ 49.497408] [<c0834820>] (__schedule) from [<c0834cc0>] (schedule+0x54/0xb8) [ 49.504491] [<c0834cc0>] (schedule) from [<c015780c>] (worker_thread+0xb4/0x550) [ 49.511921] [<c015780c>] (worker_thread) from [<c015d664>] (kthread+0x104/0x148) [ 49.519351] [<c015d664>] (kthread) from [<c0107830>] (ret_from_fork+0x14/0x24) [ 49.563684] usb 3-1: New USB device found, idVendor=05e3, idProduct=0745 [ 49.570522] usb 3-1: New USB device strings: Mfr=0, Product=1, SerialNumber=2 [ 49.577684] usb 3-1: Product: USB Storage [ 49.581887] usb 3-1: SerialNumber: 000000000902 [ 49.587894] usb-storage 3-1:1.0: USB Mass Storage device detected [ 49.596532] scsi host1: usb-storage 3-1:1.0 [ 49.601738] of_get_named_gpiod_flags: can't parse 'hpd-gpios' property of node '/connector[0]' [ 49.610869] connector-hdmi connector: failed to find video source [ 50.661720] scsi 1:0:0:0: Direct-Access Generic STORAGE DEVICE 0902 PQ: 0 ANSI: 6 [ 50.672125] of_get_named_gpiod_flags: can't parse 'hpd-gpios' property of node '/connector[0]' [ 50.681001] connector-hdmi connector: failed to find video source [ 50.918830] sd 1:0:0:0: [sda] 7882752 512-byte logical blocks: (4.04 GB/3.76 GiB) [ 50.927672] sd 1:0:0:0: [sda] Write Protect is off [ 50.932539] sd 1:0:0:0: [sda] Mode Sense: 21 00 00 00 [ 50.938860] sd 1:0:0:0: [sda] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA [ 50.954522] sda: sda1 [ 50.960682] sd 1:0:0:0: [sda] Attached SCSI removable disk
* Roger Quadros rogerq@ti.com [170216 05:44]:
+Chanwoo
On 15/02/17 23:36, Tony Lindgren wrote:
- Tony Lindgren tony@atomide.com [170215 13:01]:
- Roger Quadros rogerq@ti.com [170214 01:44]:
You can enable dwc3 trace events.
cd /sys/kernel/debug/tracing echo 1 > events/dwc3/enable echo 0 > events/dwc3/dwc3_readl/enable echo 0 > events/dwc3/dwc3_writel/enable echo 1 > free_buffer echo 2048 > buffer_size_kb
For me the issue was I had to change my sysfs scripts to start doing echo -n instead of just echo. Things are working for me now with Linux next.
Then in host mode after connecting a device, I see the following warnings with Linux next and lockdep enabled if host mode is forced with dr_mode = "host":
BTW is dr_mode = "host" still needed or is the role switching close to working now?
CONFIG_DEBUG_LOCKDEP=y CONFIG_DEBUG_ATOMIC_SLEEP=y
Looks like extcon is calling the notifiers while atomic. (spinlocks held, IRQs disabled?) Does this needs to be fixed at extcon layer or dwc3-omap should execute the mailbox in a workqueue?
Sounds like changing it in extcon might break unknown other drivers :)
Regards,
Tony
On 16/02/17 17:16, Tony Lindgren wrote:
- Roger Quadros rogerq@ti.com [170216 05:44]:
+Chanwoo
On 15/02/17 23:36, Tony Lindgren wrote:
- Tony Lindgren tony@atomide.com [170215 13:01]:
- Roger Quadros rogerq@ti.com [170214 01:44]:
You can enable dwc3 trace events.
cd /sys/kernel/debug/tracing echo 1 > events/dwc3/enable echo 0 > events/dwc3/dwc3_readl/enable echo 0 > events/dwc3/dwc3_writel/enable echo 1 > free_buffer echo 2048 > buffer_size_kb
For me the issue was I had to change my sysfs scripts to start doing echo -n instead of just echo. Things are working for me now with Linux next.
Then in host mode after connecting a device, I see the following warnings with Linux next and lockdep enabled if host mode is forced with dr_mode = "host":
BTW is dr_mode = "host" still needed or is the role switching close to working now?
dual-role is still under review. https://lkml.org/lkml/2017/2/16/254
I haven't tested it on omap5-uevm. Will keep it in mind.
CONFIG_DEBUG_LOCKDEP=y CONFIG_DEBUG_ATOMIC_SLEEP=y
Looks like extcon is calling the notifiers while atomic. (spinlocks held, IRQs disabled?) Does this needs to be fixed at extcon layer or dwc3-omap should execute the mailbox in a workqueue?
Sounds like changing it in extcon might break unknown other drivers :)
OK.
Hi Roger,
On 2017년 02월 16일 22:43, Roger Quadros wrote:
+Chanwoo
On 15/02/17 23:36, Tony Lindgren wrote:
- Tony Lindgren tony@atomide.com [170215 13:01]:
- Roger Quadros rogerq@ti.com [170214 01:44]:
You can enable dwc3 trace events.
cd /sys/kernel/debug/tracing echo 1 > events/dwc3/enable echo 0 > events/dwc3/dwc3_readl/enable echo 0 > events/dwc3/dwc3_writel/enable echo 1 > free_buffer echo 2048 > buffer_size_kb
For me the issue was I had to change my sysfs scripts to start doing echo -n instead of just echo. Things are working for me now with Linux next.
Then in host mode after connecting a device, I see the following warnings with Linux next and lockdep enabled if host mode is forced with dr_mode = "host":
CONFIG_DEBUG_LOCKDEP=y CONFIG_DEBUG_ATOMIC_SLEEP=y
Looks like extcon is calling the notifiers while atomic. (spinlocks held, IRQs disabled?) Does this needs to be fixed at extcon layer or dwc3-omap should execute the mailbox in a workqueue?
Right, Now extcon layer is working withing the spinlock range because of reducing the latency to notifier the status of external connector. I recommend that dwc3-opap better to use the workqueue.
cheers, -roger
Regards,
Tony
8< -------------------------------- [ 48.431095] BUG: sleeping function called from invalid context at kernel/locking/mutex.c:745 [ 48.439609] in_atomic(): 1, irqs_disabled(): 128, pid: 416, name: kworker/1:2 [ 48.446774] 3 locks held by kworker/1:2/416: [ 48.451058] #0: ("events_power_efficient"){.+.+.+}, at: [<c01565b0>] process_one_work+0x1f8/0x808 [ 48.460168] #1: ((&(&palmas_usb->wq_detectid)->work)){+.+...}, at: [<c01565b0>] process_one_work+0x1f8/0x808 [ 48.470226] #2: (&(&edev->lock)->rlock){......}, at: [<bf028324>] extcon_sync+0x70/0x1c8 [extcon_core] [ 48.479770] irq event stamp: 7468 [ 48.483102] hardirqs last enabled at (7467): [<c083a970>] _raw_spin_unlock_irqrestore+0x30/0x5c [ 48.491925] hardirqs last disabled at (7468): [<c083a7bc>] _raw_spin_lock_irqsave+0x1c/0x64 [ 48.500315] softirqs last enabled at (5354): [<c01f0b2c>] css_release_work_fn+0xf4/0x264 [ 48.508528] softirqs last disabled at (5352): [<c01f0b14>] css_release_work_fn+0xdc/0x264 [ 48.516741] CPU: 1 PID: 416 Comm: kworker/1:2 Not tainted 4.10.0-rc8-next-20170215+ #123 [ 48.524864] Hardware name: Generic OMAP5 (Flattened Device Tree) [ 48.530898] Workqueue: events_power_efficient palmas_gpio_id_detect [extcon_palmas] [ 48.538597] [<c0110228>] (unwind_backtrace) from [<c010c224>] (show_stack+0x10/0x14) [ 48.546379] [<c010c224>] (show_stack) from [<c04ca860>] (dump_stack+0xac/0xe0) [ 48.553637] [<c04ca860>] (dump_stack) from [<c0165fa0>] (___might_sleep+0x17c/0x2a4) [ 48.561416] [<c0165fa0>] (___might_sleep) from [<c0835fec>] (__mutex_lock+0x28/0x9f8) [ 48.569281] [<c0835fec>] (__mutex_lock) from [<c08369d8>] (mutex_lock_nested+0x1c/0x24) [ 48.577322] [<c08369d8>] (mutex_lock_nested) from [<c05478dc>] (regulator_enable+0x40/0x1dc) [ 48.585803] [<c05478dc>] (regulator_enable) from [<bf29d32c>] (dwc3_omap_set_mailbox+0xcc/0x184 [dwc3_omap]) [ 48.595705] [<bf29d32c>] (dwc3_omap_set_mailbox [dwc3_omap]) from [<bf29d7ec>] (dwc3_omap_id_notifier+0x14/0x1c [dwc3_omap]) [ 48.606979] [<bf29d7ec>] (dwc3_omap_id_notifier [dwc3_omap]) from [<c015f3ac>] (notifier_call_chain+0x44/0x80) [ 48.617028] [<c015f3ac>] (notifier_call_chain) from [<c015f520>] (raw_notifier_call_chain+0x18/0x20) [ 48.626209] [<c015f520>] (raw_notifier_call_chain) from [<bf028344>] (extcon_sync+0x90/0x1c8 [extcon_core]) [ 48.636004] [<bf028344>] (extcon_sync [extcon_core]) from [<c015666c>] (process_one_work+0x2b4/0x808) [ 48.645268] [<c015666c>] (process_one_work) from [<c0157794>] (worker_thread+0x3c/0x550) [ 48.653396] [<c0157794>] (worker_thread) from [<c015d664>] (kthread+0x104/0x148) [ 48.660828] [<c015d664>] (kthread) from [<c0107830>] (ret_from_fork+0x14/0x24) [ 48.668313] BUG: scheduling while atomic: kworker/1:2/416/0x00000002 [ 48.674717] 5 locks held by kworker/1:2/416: [ 48.679003] #0: ("events_power_efficient"){.+.+.+}, at: [<c01565b0>] process_one_work+0x1f8/0x808 [ 48.688140] #1: ((&(&palmas_usb->wq_detectid)->work)){+.+...}, at: [<c01565b0>] process_one_work+0x1f8/0x808 [ 48.698231] #2: (&(&edev->lock)->rlock){+.+...}, at: [<bf028324>] extcon_sync+0x70/0x1c8 [extcon_core] [ 48.707807] #3: (&rdev->mutex){+.+.+.}, at: [<c05478dc>] regulator_enable+0x40/0x1dc [ 48.715803] #4: (palmas:546:(&palmas_regmap_config[i])->lock){+.+.+.}, at: [<c05aa170>] regmap_read+0x2c/0x5c [ 48.725983] Modules linked in: usb_f_ecm usb_storage cppi41 am35x musb_dsps musb_am335x omap2430 phy_cpcap_usb phy_dm816x_usb phy_am335x phy_am335x_control phy_twl6030_usb phy_twl4030_usb musb_hdrc mwifiex_sdio mwifiex arc4 wlcore_sdio wl18xx wl12xx wlcore mac80211 cfg80211 omapdrm drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops drm panel_dsi_cm lm3532_bl atmel_mxt_ts omap4_keypad matrix_keymap evdev ti_lmu_backlight ti_lmu connector_hdmi omapdss cfbimgblt cfbfillrect cfbcopyarea gpio_pca953x hid_generic usbhid smsc95xx smsc75xx usbnet usb_f_acm u_ether usb_f_mass_storage usb_f_serial u_serial xhci_plat_hcd xhci_hcd dwc3_omap dwc3 ohci_omap3 ohci_hcd ehci_omap ehci_hcd phy_omap_usb2 phy_generic libcomposite udc_core snd_soc_simple_card snd_soc_simple_card_utils snd_usb_audio snd_usbmidi_lib [ 48.797725] usbcore usb_common snd_soc_omap_mcbsp snd_soc_omap_dmic snd_soc_omap_twl4030 snd_soc_omap_abe_twl6040 snd_soc_omap_mcpdm snd_soc_twl6040 snd_soc_twl4030 snd_soc_omap snd_soc_core snd_hwdep snd_pcm_dmaengine snd_pcm snd_timer snd_rawmidi snd soundcore rtc_ds1307 hwmon rtc_palmas rtc_twl palmas_pwrbutton extcon_palmas extcon_core ti_soc_thermal clk_palmas lib80211 ccm [ 48.831540] CPU: 1 PID: 416 Comm: kworker/1:2 Tainted: G W 4.10.0-rc8-next-20170215+ #123 [ 48.840892] Hardware name: Generic OMAP5 (Flattened Device Tree) [ 48.846926] Workqueue: events_power_efficient palmas_gpio_id_detect [extcon_palmas] [ 48.854623] [<c0110228>] (unwind_backtrace) from [<c010c224>] (show_stack+0x10/0x14) [ 48.862403] [<c010c224>] (show_stack) from [<c04ca860>] (dump_stack+0xac/0xe0) [ 48.869661] [<c04ca860>] (dump_stack) from [<c0165dec>] (__schedule_bug+0x6c/0xa4) [ 48.877270] [<c0165dec>] (__schedule_bug) from [<c0834820>] (__schedule+0xa38/0xe84) [ 48.885051] [<c0834820>] (__schedule) from [<c0834cc0>] (schedule+0x54/0xb8) [ 48.892133] [<c0834cc0>] (schedule) from [<c0839b98>] (schedule_timeout+0x23c/0x4a0) [ 48.899921] [<c0839b98>] (schedule_timeout) from [<c08357b4>] (wait_for_common+0xa8/0x164) [ 48.908230] [<c08357b4>] (wait_for_common) from [<c066c6e0>] (omap_i2c_xfer+0x3d8/0x550) [ 48.916356] [<c066c6e0>] (omap_i2c_xfer) from [<c0667f14>] (__i2c_transfer+0x13c/0x9d8) [ 48.924396] [<c0667f14>] (__i2c_transfer) from [<c0668820>] (i2c_transfer+0x70/0xb4) [ 48.932175] [<c0668820>] (i2c_transfer) from [<c05b0f7c>] (regmap_i2c_read+0x48/0x64) [ 48.940048] [<c05b0f7c>] (regmap_i2c_read) from [<c05aabd4>] (_regmap_raw_read+0xe4/0x488) [ 48.948350] [<c05aabd4>] (_regmap_raw_read) from [<c05aaf9c>] (_regmap_bus_read+0x24/0x4c) [ 48.956651] [<c05aaf9c>] (_regmap_bus_read) from [<c05a9f3c>] (_regmap_read+0x64/0x26c) [ 48.964690] [<c05a9f3c>] (_regmap_read) from [<c05aa180>] (regmap_read+0x3c/0x5c) [ 48.972207] [<c05aa180>] (regmap_read) from [<c05490c8>] (regulator_is_enabled_regmap+0x20/0x9c) [ 48.981033] [<c05490c8>] (regulator_is_enabled_regmap) from [<c05479f4>] (regulator_enable+0x158/0x1dc) [ 48.990472] [<c05479f4>] (regulator_enable) from [<bf29d32c>] (dwc3_omap_set_mailbox+0xcc/0x184 [dwc3_omap]) [ 49.000387] [<bf29d32c>] (dwc3_omap_set_mailbox [dwc3_omap]) from [<bf29d7ec>] (dwc3_omap_id_notifier+0x14/0x1c [dwc3_omap]) [ 49.011661] [<bf29d7ec>] (dwc3_omap_id_notifier [dwc3_omap]) from [<c015f3ac>] (notifier_call_chain+0x44/0x80) [ 49.021710] [<c015f3ac>] (notifier_call_chain) from [<c015f520>] (raw_notifier_call_chain+0x18/0x20) [ 49.030892] [<c015f520>] (raw_notifier_call_chain) from [<bf028344>] (extcon_sync+0x90/0x1c8 [extcon_core]) [ 49.040688] [<bf028344>] (extcon_sync [extcon_core]) from [<c015666c>] (process_one_work+0x2b4/0x808) [ 49.049952] [<c015666c>] (process_one_work) from [<c0157794>] (worker_thread+0x3c/0x550) [ 49.058080] [<c0157794>] (worker_thread) from [<c015d664>] (kthread+0x104/0x148) [ 49.065509] [<c015d664>] (kthread) from [<c0107830>] (ret_from_fork+0x14/0x24)
[ 49.075275] =============================== [ 49.079503] [ ERR: suspicious RCU usage. ] [ 49.083774] 4.10.0-rc8-next-20170215+ #123 Tainted: G W [ 49.090211] ------------------------------- [ 49.094454] ./include/trace/events/kmem.h:51 suspicious rcu_dereference_check() usage! [ 49.102470] other info that might help us debug this:
[ 49.110581] rcu_scheduler_active = 2, debug_locks = 0 [ 49.117181] 2 locks held by kworker/1:2/416: [ 49.121551] #0: ("events_power_efficient"){.+.+.+}, at: [<c01565b0>] process_one_work+0x1f8/0x808 [ 49.130715] #1: ((&(&palmas_usb->wq_detectid)->work)){+.+.+.}, at: [<c01565b0>] process_one_work+0x1f8/0x808 [ 49.140845] stack backtrace: [ 49.145264] CPU: 1 PID: 416 Comm: kworker/1:2 Tainted: G W 4.10.0-rc8-next-20170215+ #123 [ 49.154614] Hardware name: Generic OMAP5 (Flattened Device Tree) [ 49.160649] Workqueue: events_power_efficient palmas_gpio_id_detect [extcon_palmas] [ 49.168345] [<c0110228>] (unwind_backtrace) from [<c010c224>] (show_stack+0x10/0x14) [ 49.176123] [<c010c224>] (show_stack) from [<c04ca860>] (dump_stack+0xac/0xe0) [ 49.183385] [<c04ca860>] (dump_stack) from [<c02aa500>] (kmem_cache_alloc_trace+0x2fc/0x364) [ 49.191865] [<c02aa500>] (kmem_cache_alloc_trace) from [<c04cd05c>] (kobject_uevent_env+0xac/0x4f4) [ 49.200959] [<c04cd05c>] (kobject_uevent_env) from [<bf028424>] (extcon_sync+0x170/0x1c8 [extcon_core]) [ 49.210403] [<bf028424>] (extcon_sync [extcon_core]) from [<c015666c>] (process_one_work+0x2b4/0x808) [ 49.219666] [<c015666c>] (process_one_work) from [<c0157794>] (worker_thread+0x3c/0x550) [ 49.227794] [<c0157794>] (worker_thread) from [<c015d664>] (kthread+0x104/0x148) [ 49.235225] [<c015d664>] (kthread) from [<c0107830>] (ret_from_fork+0x14/0x24) [ 49.242589] BUG: workqueue leaked lock or atomic: kworker/1:2/0xffffffff/416 last function: palmas_gpio_id_detect [extcon_palmas] [ 49.256144] INFO: lockdep is turned off. [ 49.260099] CPU: 1 PID: 416 Comm: kworker/1:2 Tainted: G W 4.10.0-rc8-next-20170215+ #123 [ 49.269442] Hardware name: Generic OMAP5 (Flattened Device Tree) [ 49.275477] Workqueue: events_power_efficient palmas_gpio_id_detect [extcon_palmas] [ 49.283174] [<c0110228>] (unwind_backtrace) from [<c010c224>] (show_stack+0x10/0x14) [ 49.290953] [<c010c224>] (show_stack) from [<c04ca860>] (dump_stack+0xac/0xe0) [ 49.298210] [<c04ca860>] (dump_stack) from [<c0156998>] (process_one_work+0x5e0/0x808) [ 49.306165] [<c0156998>] (process_one_work) from [<c0157794>] (worker_thread+0x3c/0x550) [ 49.314293] [<c0157794>] (worker_thread) from [<c015d664>] (kthread+0x104/0x148) [ 49.321723] [<c015d664>] (kthread) from [<c0107830>] (ret_from_fork+0x14/0x24) [ 49.328998] BUG: scheduling while atomic: kworker/1:2/416/0x00000000 [ 49.335450] INFO: lockdep is turned off. [ 49.339433] Modules linked in: usb_f_ecm usb_storage cppi41 am35x musb_dsps musb_am335x omap2430 phy_cpcap_usb phy_dm816x_usb phy_am335x phy_am335x_control phy_twl6030_usb phy_twl4030_usb musb_hdrc mwifiex_sdio mwifiex arc4 wlcore_sdio wl18xx wl12xx wlcore mac80211 cfg80211 omapdrm drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops drm panel_dsi_cm lm3532_bl atmel_mxt_ts omap4_keypad matrix_keymap evdev ti_lmu_backlight ti_lmu connector_hdmi omapdss cfbimgblt cfbfillrect cfbcopyarea gpio_pca953x hid_generic usbhid smsc95xx smsc75xx usbnet usb_f_acm u_ether usb_f_mass_storage usb_f_serial u_serial xhci_plat_hcd xhci_hcd dwc3_omap dwc3 ohci_omap3 ohci_hcd ehci_omap ehci_hcd phy_omap_usb2 phy_generic libcomposite udc_core snd_soc_simple_card snd_soc_simple_card_utils snd_usb_audio snd_usbmidi_lib [ 49.339938] usb 3-1: new high-speed USB device number 2 using xhci-hcd [ 49.417777] usbcore usb_common snd_soc_omap_mcbsp snd_soc_omap_dmic snd_soc_omap_twl4030 snd_soc_omap_abe_twl6040 snd_soc_omap_mcpdm snd_soc_twl6040 snd_soc_twl4030 snd_soc_omap snd_soc_core snd_hwdep snd_pcm_dmaengine snd_pcm snd_timer snd_rawmidi snd soundcore rtc_ds1307 hwmon rtc_palmas rtc_twl palmas_pwrbutton extcon_palmas extcon_core ti_soc_thermal clk_palmas lib80211 ccm [ 49.451601] CPU: 1 PID: 416 Comm: kworker/1:2 Tainted: G W 4.10.0-rc8-next-20170215+ #123 [ 49.460944] Hardware name: Generic OMAP5 (Flattened Device Tree) [ 49.466986] [<c0110228>] (unwind_backtrace) from [<c010c224>] (show_stack+0x10/0x14) [ 49.474764] [<c010c224>] (show_stack) from [<c04ca860>] (dump_stack+0xac/0xe0) [ 49.482021] [<c04ca860>] (dump_stack) from [<c0165dec>] (__schedule_bug+0x6c/0xa4) [ 49.489628] [<c0165dec>] (__schedule_bug) from [<c0834820>] (__schedule+0xa38/0xe84) [ 49.497408] [<c0834820>] (__schedule) from [<c0834cc0>] (schedule+0x54/0xb8) [ 49.504491] [<c0834cc0>] (schedule) from [<c015780c>] (worker_thread+0xb4/0x550) [ 49.511921] [<c015780c>] (worker_thread) from [<c015d664>] (kthread+0x104/0x148) [ 49.519351] [<c015d664>] (kthread) from [<c0107830>] (ret_from_fork+0x14/0x24) [ 49.563684] usb 3-1: New USB device found, idVendor=05e3, idProduct=0745 [ 49.570522] usb 3-1: New USB device strings: Mfr=0, Product=1, SerialNumber=2 [ 49.577684] usb 3-1: Product: USB Storage [ 49.581887] usb 3-1: SerialNumber: 000000000902 [ 49.587894] usb-storage 3-1:1.0: USB Mass Storage device detected [ 49.596532] scsi host1: usb-storage 3-1:1.0 [ 49.601738] of_get_named_gpiod_flags: can't parse 'hpd-gpios' property of node '/connector[0]' [ 49.610869] connector-hdmi connector: failed to find video source [ 50.661720] scsi 1:0:0:0: Direct-Access Generic STORAGE DEVICE 0902 PQ: 0 ANSI: 6 [ 50.672125] of_get_named_gpiod_flags: can't parse 'hpd-gpios' property of node '/connector[0]' [ 50.681001] connector-hdmi connector: failed to find video source [ 50.918830] sd 1:0:0:0: [sda] 7882752 512-byte logical blocks: (4.04 GB/3.76 GiB) [ 50.927672] sd 1:0:0:0: [sda] Write Protect is off [ 50.932539] sd 1:0:0:0: [sda] Mode Sense: 21 00 00 00 [ 50.938860] sd 1:0:0:0: [sda] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA [ 50.954522] sda: sda1 [ 50.960682] sd 1:0:0:0: [sda] Attached SCSI removable disk
On 17/02/17 02:02, Chanwoo Choi wrote:
Hi Roger,
On 2017년 02월 16일 22:43, Roger Quadros wrote:
+Chanwoo
On 15/02/17 23:36, Tony Lindgren wrote:
- Tony Lindgren tony@atomide.com [170215 13:01]:
- Roger Quadros rogerq@ti.com [170214 01:44]:
You can enable dwc3 trace events.
cd /sys/kernel/debug/tracing echo 1 > events/dwc3/enable echo 0 > events/dwc3/dwc3_readl/enable echo 0 > events/dwc3/dwc3_writel/enable echo 1 > free_buffer echo 2048 > buffer_size_kb
For me the issue was I had to change my sysfs scripts to start doing echo -n instead of just echo. Things are working for me now with Linux next.
Then in host mode after connecting a device, I see the following warnings with Linux next and lockdep enabled if host mode is forced with dr_mode = "host":
CONFIG_DEBUG_LOCKDEP=y CONFIG_DEBUG_ATOMIC_SLEEP=y
Looks like extcon is calling the notifiers while atomic. (spinlocks held, IRQs disabled?) Does this needs to be fixed at extcon layer or dwc3-omap should execute the mailbox in a workqueue?
Right, Now extcon layer is working withing the spinlock range because of reducing the latency to notifier the status of external connector. I recommend that dwc3-opap better to use the workqueue.
OK Chanwoo. Thanks.
Hi Roger, I found time to look deeper into this issue and have found it.
Maybe some u-boot dependency? I use a modified 2016.11. Should find time do more testing...
Yeah. might be a good idea to try different u-boot versions.
Is there a way to debug what dwc3 is doing or not doing?
You can enable dwc3 trace events.
cd /sys/kernel/debug/tracing echo 1 > events/dwc3/enable
well, I did not find events/dwc3 but a boot log trace of dwc3 failing.
After checking with printk if the probe function did succeed, it turned out that the id pin in extcon-palmas did always return -EPROBE_DEFER making the dcw3 driver finally fail to probe.
This turned out to be a disabled CONFIG_GPIO_PALMAS in our defconfig (we do not use the omap2plus). No idea why it was disabled and why it did work up to 4.8 or so... Maybe some detail changed in probing sequence or dependencies.
Perhaps CONFIG_USB_DWC3_OMAP could enforce CONFIG_GPIO_PALMAS as well.
BR and thanks for suggesting to look at tracing/events which directed me to the solution, Nikolaus
Nikolaus,
On 16/02/17 15:43, H. Nikolaus Schaller wrote:
Hi Roger, I found time to look deeper into this issue and have found it.
Maybe some u-boot dependency? I use a modified 2016.11. Should find time do more testing...
Yeah. might be a good idea to try different u-boot versions.
Is there a way to debug what dwc3 is doing or not doing?
You can enable dwc3 trace events.
cd /sys/kernel/debug/tracing echo 1 > events/dwc3/enable
well, I did not find events/dwc3 but a boot log trace of dwc3 failing.
After checking with printk if the probe function did succeed, it turned out that the id pin in extcon-palmas did always return -EPROBE_DEFER making the dcw3 driver finally fail to probe.
This turned out to be a disabled CONFIG_GPIO_PALMAS in our defconfig (we do not use the omap2plus). No idea why it was disabled and why it did work up to 4.8 or so... Maybe some detail changed in probing sequence or dependencies.
Great!!
Perhaps CONFIG_USB_DWC3_OMAP could enforce CONFIG_GPIO_PALMAS as well.
Unfortunately we can't do that as DWC3_OMAP doesn't need PALMAS to work. It can even work with GPIOs for VBUS and ID events or some other non-palmas USB companion chip.
The board specific config must enable CONFIG_GPIO_PALMAS.
BR and thanks for suggesting to look at tracing/events which directed me to the solution, Nikolaus
-
Chanwoo Choi -
H. Nikolaus Schaller -
Roger Quadros -
Tony Lindgren