Bug 186191

Summary:	i2c-MSHW0030:00 takes more than 2 seconds to suspend, call trace in dmesg - Surface Pro 3
Product:	ACPI	Reporter:	Zhang Rui (rui.zhang)
Component:	Power-Sleep-Wake	Assignee:	Lv Zheng (lv.zheng)
Status:	CLOSED UNREPRODUCIBLE
Severity:	normal
Priority:	P1
Hardware:	All
OS:	Linux
Kernel Version:	All	Subsystem:
Regression:	No	Bisected commit-id:
Bug Depends on:
Bug Blocks:	178231
Attachments:	suspend/resume dmesg output analyze_suspend output hid/for-next(4.9-rc6+) analyze_suspend output hid/for-next(4.9-rc6+) suspend/resume dmesg output

Description Zhang Rui 2016-11-01 07:07:54 UTC

the MSHW0030 device takes more than 2 seconds to suspend. and there is call trace related with ACPI in dmesg output,

[   70.407540] i2c_designware INT33C2:00: controller timed out
[   70.407852] i2c_hid i2c-MSHW0030:00: failed to change power setting.
[   71.431640] i2c_designware INT33C2:00: controller timed out
[   71.431656] i2c_hid i2c-MSHW0030:00: failed to change power setting.
[   71.431921] sd 0:0:0:0: [sda] Synchronizing SCSI cache
[   71.432461] ------------[ cut here ]------------
[   71.432472] WARNING: CPU: 3 PID: 1717 at drivers/clk/clk.c:594 clk_core_disable+0xf2/0x130
[   71.432519] Modules linked in: btusb btintel bluetooth hid_sensor_accel_3d hid_sensor_incl_3d hid_sensor_gyro_3d hid_sensor_rotation hid_sensor_als hid_sensor_magn_3d hid_sensor_trigger hid_sensor_iio_common industrialio_triggered_buffer kfifo_buf industrialio snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_codec_generic hid_sensor_hub hid_multitouch mfd_core mwifiex_pcie mwifiex snd_hda_intel snd_hda_codec cfg80211 snd_hwdep snd_hda_core snd_pcm input_leds led_class snd_timer sg snd surfacepro3_button 8250_dw dw_dmac i2c_designware_platform 8250 dw_dmac_core i2c_designware_core 8250_base serial_core parport_pc ppdev lp parport hid_microsoft hid_generic i915 ahci libahci libata xhci_pci xhci_hcd gpio_lynxpoint i2c_hid
[   71.432523] CPU: 3 PID: 1717 Comm: analyze_suspend Tainted: G        W       4.8.0+ #30
[   71.432525] Hardware name: Microsoft Corporation Surface Pro 3/Surface Pro 3, BIOS 3.11.0760 03/16/2015
[   71.432530]  ffffc9000166fb28 ffffffff82490243 0000000000000000 0000000000000000
[   71.432533]  ffffc9000166fb68 ffffffff820dbd4b 00000252821aee89 ffff88014a2bce00
[   71.432536]  ffff88014a2bce00 ffffffff82534e73 ffff880146db60a8 ffffffff82d85fce
[   71.432537] Call Trace:
[   71.432546]  [<ffffffff82490243>] dump_stack+0x63/0x90
[   71.432553]  [<ffffffff820dbd4b>] __warn+0xcb/0xf0
[   71.432560]  [<ffffffff82534e73>] ? acpi_subsys_resume_early+0x21/0x21
[   71.432563]  [<ffffffff820dbe7d>] warn_slowpath_null+0x1d/0x20
[   71.432568]  [<ffffffff825a2552>] clk_core_disable+0xf2/0x130
[   71.432572]  [<ffffffff825a25af>] clk_core_disable_lock+0x1f/0x30
[   71.432576]  [<ffffffff825a25df>] clk_disable+0x1f/0x30
[   71.432582]  [<ffffffffc02b905b>] i2c_dw_plat_prepare_clk+0x2b/0x70 [i2c_designware_platform]
[   71.432586]  [<ffffffff82534e73>] ? acpi_subsys_resume_early+0x21/0x21
[   71.432590]  [<ffffffffc02b9103>] dw_i2c_plat_suspend+0x23/0x30 [i2c_designware_platform]
[   71.432597]  [<ffffffff8267fadb>] pm_generic_suspend+0x2b/0x40
[   71.432601]  [<ffffffff82534e8f>] acpi_subsys_suspend+0x1c/0x1f
[   71.432604]  [<ffffffff8268405e>] dpm_run_callback+0x4e/0x130
[   71.432608]  [<ffffffff82684df8>] __device_suspend+0x148/0x370
[   71.432611]  [<ffffffff8268679c>] dpm_suspend+0x12c/0x2e0
[   71.432615]  [<ffffffff82686da0>] dpm_suspend_start+0x50/0x60
[   71.432622]  [<ffffffff8212c9ef>] suspend_devices_and_enter+0xcf/0x700
[   71.432626]  [<ffffffff8212d34a>] pm_suspend+0x32a/0x3a0
[   71.432630]  [<ffffffff8212bb2c>] state_store+0x7c/0xe0
[   71.432635]  [<ffffffff8249257f>] kobj_attr_store+0xf/0x20
[   71.432641]  [<ffffffff822fb2f7>] sysfs_kf_write+0x37/0x40
[   71.432645]  [<ffffffff822fa647>] kernfs_fop_write+0x117/0x190
[   71.432650]  [<ffffffff8227a877>] __vfs_write+0x37/0x160
[   71.432653]  [<ffffffff8227afa8>] vfs_write+0xb8/0x1b0
[   71.432657]  [<ffffffff8227c415>] SyS_write+0x55/0xc0
[   71.432663]  [<ffffffff8290f73b>] entry_SYSCALL_64_fastpath+0x1e/0xad
[   71.432665] ---[ end trace 9303036f6b697fd4 ]---
[   71.432667] ------------[ cut here ]------------
[   71.432672] WARNING: CPU: 3 PID: 1717 at drivers/clk/clk.c:476 clk_core_unprepare+0x120/0x140
[   71.432703] Modules linked in: btusb btintel bluetooth hid_sensor_accel_3d hid_sensor_incl_3d hid_sensor_gyro_3d hid_sensor_rotation hid_sensor_als hid_sensor_magn_3d hid_sensor_trigger hid_sensor_iio_common industrialio_triggered_buffer kfifo_buf industrialio snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_codec_generic hid_sensor_hub hid_multitouch mfd_core mwifiex_pcie mwifiex snd_hda_intel snd_hda_codec cfg80211 snd_hwdep snd_hda_core snd_pcm input_leds led_class snd_timer sg snd surfacepro3_button 8250_dw dw_dmac i2c_designware_platform 8250 dw_dmac_core i2c_designware_core 8250_base serial_core parport_pc ppdev lp parport hid_microsoft hid_generic i915 ahci libahci libata xhci_pci xhci_hcd gpio_lynxpoint i2c_hid
[   71.432706] CPU: 3 PID: 1717 Comm: analyze_suspend Tainted: G        W       4.8.0+ #30
[   71.432707] Hardware name: Microsoft Corporation Surface Pro 3/Surface Pro 3, BIOS 3.11.0760 03/16/2015
[   71.432710]  ffffc9000166fb40 ffffffff82490243 0000000000000000 0000000000000000
[   71.432714]  ffffc9000166fb80 ffffffff820dbd4b 000001dc82534e73 ffff88014a2bce00
[   71.432717]  0000000000000000 ffffffff82534e73 ffff880146db60a8 ffffffff82d85fce
[   71.432717] Call Trace:
[   71.432721]  [<ffffffff82490243>] dump_stack+0x63/0x90
[   71.432725]  [<ffffffff820dbd4b>] __warn+0xcb/0xf0
[   71.432729]  [<ffffffff82534e73>] ? acpi_subsys_resume_early+0x21/0x21
[   71.432732]  [<ffffffff820dbe7d>] warn_slowpath_null+0x1d/0x20
[   71.432736]  [<ffffffff825a1b60>] clk_core_unprepare+0x120/0x140
[   71.432741]  [<ffffffff825a2448>] clk_unprepare+0x28/0x40
[   71.432744]  [<ffffffffc02b9066>] i2c_dw_plat_prepare_clk+0x36/0x70 [i2c_designware_platform]
[   71.432748]  [<ffffffff82534e73>] ? acpi_subsys_resume_early+0x21/0x21
[   71.432751]  [<ffffffffc02b9103>] dw_i2c_plat_suspend+0x23/0x30 [i2c_designware_platform]
[   71.432755]  [<ffffffff8267fadb>] pm_generic_suspend+0x2b/0x40
[   71.432760]  [<ffffffff82534e8f>] acpi_subsys_suspend+0x1c/0x1f
[   71.432763]  [<ffffffff8268405e>] dpm_run_callback+0x4e/0x130
[   71.432766]  [<ffffffff82684df8>] __device_suspend+0x148/0x370
[   71.432769]  [<ffffffff8268679c>] dpm_suspend+0x12c/0x2e0
[   71.432772]  [<ffffffff82686da0>] dpm_suspend_start+0x50/0x60
[   71.432777]  [<ffffffff8212c9ef>] suspend_devices_and_enter+0xcf/0x700
[   71.432781]  [<ffffffff8212d34a>] pm_suspend+0x32a/0x3a0
[   71.432785]  [<ffffffff8212bb2c>] state_store+0x7c/0xe0
[   71.432790]  [<ffffffff8249257f>] kobj_attr_store+0xf/0x20
[   71.432793]  [<ffffffff822fb2f7>] sysfs_kf_write+0x37/0x40
[   71.432797]  [<ffffffff822fa647>] kernfs_fop_write+0x117/0x190
[   71.432800]  [<ffffffff8227a877>] __vfs_write+0x37/0x160
[   71.432804]  [<ffffffff8227afa8>] vfs_write+0xb8/0x1b0
[   71.432807]  [<ffffffff8227c415>] SyS_write+0x55/0xc0
[   71.432811]  [<ffffffff8290f73b>] entry_SYSCALL_64_fastpath+0x1e/0xad
[   71.432813] ---[ end trace 9303036f6b697fd5 ]---
[   71.433312] ACPI : EC: +++++ event blocked +++++
[   71.433832] sd 0:0:0:0: [sda] Stopping disk
[   72.807221] PM: suspend of devices complete after 3452.130 msecs

Comment 1 Zhang Rui 2016-11-01 07:08:50 UTC

Created attachment 243401 [details]
suspend/resume dmesg output

Comment 2 Zhang Rui 2016-11-01 07:09:25 UTC

Created attachment 243411 [details]
analyze_suspend output

Comment 3 Lv Zheng 2016-12-16 07:26:52 UTC

I'll try recent HID tree and paste new test result later.

Comment 4 Lv Zheng 2016-12-19 08:20:15 UTC

Using the hid/for-next branch, the problem doesn't exist.
I'll upload an analyze_suspend.py result later.

Thanks
Lv

Comment 5 Lv Zheng 2016-12-19 08:22:11 UTC

Created attachment 248021 [details]
hid/for-next(4.9-rc6+) analyze_suspend output

Comment 6 Lv Zheng 2016-12-19 08:22:53 UTC

Created attachment 248031 [details]
hid/for-next(4.9-rc6+) suspend/resume dmesg output