Re: [PATCH] ACPI / LPSS: Don't skip late system PM ops for hibernate on BYT/CHT

From: Robert R. Howell
Date: Thu May 09 2019 - 14:11:46 EST

Hi Hans

On 5/9/19 2:50 AM, Hans de Goede wrote:

>
> Hi,
>
> On 09-05-19 06:24, Robert R. Howell wrote:
>> On 4/30/19 8:39 AM, Hans de Goede wrote:
>>>

>>>
>>> I've just tried to reproduce the "Error i2c_dw_xfer call while suspended" error
>>> on suspend/resume on my own T100TA and I could not reproduce this.
>>>
>>> Can you try without the BT keyboard paired and waking up from suspend using the
>>> tablet part's power-button ?
>>>
>>> Also do you still have the scripts to rmmod some modules before suspend ?
>>>
>>
>> The T100TA keyboard is actually a hardwired connection rather than Bluetooth but I
>> did physically disconnect the keyboard, and also unpaired all the actual Bluetooth
>> devices (such as the mouse) and then powered down the T100TA bluetooth adapter.
>> When I suspend, then resume using the tablet power button, I still get the
>> i2c_dw_xfererror error during the resume. But whatever causes this error isn't fatal,
>> in the sense that after resume the sound and other i2c functions do still work OK.
>>
>> While I always get this i2c_dw_xfer error on resume from suspend or hibernation on the T100TA,
>> I also have a T100TAM and curiously, it NEVER shows that error -- although all the
>> other suspend and hibernate behavior seems similar. I'm not sure if the following could
>> be the difference, but the T100TA uses an i2c connected ATML1000 touchscreen controller
>> while the T100TAM uses an i2c connected SIS0817 touchscreen controller. Other than that
>> the hardware seems almost identical.
>
> I've been testing on an actual T100TA, with the ATML1000 touchscreen controller.
>
> Maybe it is a difference in BIOS version, my T100TA is running the latest BIOS, what
> is the output of:
>
> cat /sys/class/dmi/id/bios_version /sys/class/dmi/id/bios_date
>
On the T100TA which shows the i2c_dw_xfer error the above cat reports:
T100TA.307
05/09/2014

while the T100TA which does NOT show the i2c_dw_xfer error reports:
T100TAM.205
07/25/2014
>
> Also do you perhaps have a microsd card inserted? (I'm trying to figure out the
> different between our setups so that I can hopefully reproduce the issue myself).
>
I do have a microsd card inserted in both the T100TA and the T100TAM.
>
>> Regarding scripts, while I do still need a systemd hibernate script which removes the
>> brcmfmac and the hci_uart (bluetooth related) drivers, I've found that I no longer need
>> any script for suspend.
>
> Ok, so you are not doing any rmmod-s on suspend, right?
>
Correct -- I am NOT using a script and am not doing any explicit rmmod's on suspend, just on hibernate.
> Regards,
>
> Hans

All my previous tests were done using a 5.1.0-rc5, 5.1.0-rc3, or earlier kernel.
But I just compiled the released 5.1.0 kernel and the behavior has changed for the T100TA,
resulting in a different i2c error and a call trace. (I still continue to NOT see any
suspend/resume errors on the T100TAM.)

Note that for all the tests described in this message I'm applying your patch
regarding .poweroff_noirq and .restore_noirq, and I'm applying my own patch removing the
DPM_FLAG_SMART_SUSPEND flag. I haven't yet tried to explore varying those patches
for the 5.1.0 release as I did for the earlier rc's, as described in previous messages.

On the 5.1.0-rc5 and earlier kernels running on the T100TA I consistently get the
"i2c_designware 80860F41:00: Error i2c_dw_xfer call while suspended"
error on every resume from suspend, but I've never seen the errors I'm about
to report for the new release kernel. I've rebooted my T100TA using 5.1.0-rc5
several times to confirm that old behavior is still true.

With my newly compiled 5.1.0 release on the T100TA I now see a different i2c error on
the very first suspend/resume cycle after booting. However subsequent suspend/resume
cycles do not show any errors, neither the one seen on the first cycle, nor the
i2c_dw_xfer errors seen under 5.1.0-rc5. I've rebooted a number of times to see if the
behavior is consistent, and it always seems to follow the pattern of the error and
call trace on just the first suspend/resume cycle.

Obviously something has changed in the relevant code between 5.1.0-rc5 and 5.1.0 release.
Since the behavior it is consistent, if the following dmesg output isn't enough to sort
that out I can try building the intermediate rc6 and rc7, or run a more detailed bisect.
But because this new error results in a call trace, perhaps that will be enough to determine
what is going wrong.

Once again, let me know if I can do any further tests, or if you want a full copy of
the (earlier parts of the) dmesg output.

Bob

--- dmesg output from a T100TA running 5.1.0 (released) where the first suspend/resume cycle results ----
--- in an "i2c_designware 80860F41:00: Transfer while suspended" error but subsequent cycles work OK. ----

[ 35.818537] Bluetooth: RFCOMM ver 1.11
[ 54.556518] NET: Registered protocol family 38
[ 55.276584] input: MX Anywhere 2 Keyboard as /devices/virtual/misc/uhid/0005:046D:B013.0005/input/input24
[ 55.276825] input: MX Anywhere 2 Mouse as /devices/virtual/misc/uhid/0005:046D:B013.0005/input/input25
[ 55.277710] hid-generic 0005:046D:B013.0005: input,hidraw4: BLUETOOTH HID v0.07 Keyboard [MX Anywhere 2] on 74:D0:2B:DF:77:E9
[ 78.837456] PM: suspend entry (s2idle)
[ 78.837460] PM: Syncing filesystems ... done.
[ 79.771859] Freezing user space processes ... (elapsed 0.002 seconds) done.
[ 79.774610] OOM killer disabled.
[ 79.774611] Freezing remaining freezable tasks ... (elapsed 0.000 seconds) done.
[ 85.811298] ------------[ cut here ]------------
[ 85.811310] i2c_designware 80860F41:00: Transfer while suspended
[ 85.811382] WARNING: CPU: 1 PID: 7 at drivers/i2c/busses/i2c-designware-master.c:429 i2c_dw_xfer+0x95/0x277
[ 85.811387] Modules linked in: uhid algif_hash algif_skcipher af_alg rfcomm xt_tcpudp ip6t_rpfilter ip6t_REJECT nf_reject_ipv6 ipt_REJECT nf_reject_ipv4 xt_conntrack nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 libcrc32c af_packet ip_set nfnetlink ebtable_nat ebtable_broute bridge stp llc ip6table_mangle ip6table_raw ip6table_security iptable_mangle iptable_raw iptable_security ebtable_filter ebtables ip6table_filter ip6_tables iptable_filter ip_tables x_tables cmac bnep msr snd_soc_sst_bytcr_rt5640 fuse iTCO_wdt iTCO_vendor_support intel_powerclamp coretemp gpio_keys kvm_intel kvm brcmfmac irqbypass brcmutil crc32_pclmul cfg80211 crc32c_intel aesni_intel aes_x86_64 snd_intel_sst_acpi crypto_simd snd_intel_sst_core cryptd glue_helper snd_soc_sst_atom_hifi2_platform hci_uart asus_nb_wmi pcspkr snd_soc_acpi_intel_match snd_soc_rt5640 snd_soc_acpi joydev snd_soc_rl6231 btqca ak8975 snd_soc_core btrtl btbcm snd_hdmi_lpe_audio btintel snd_compress lpc_ich bluetooth ac97_bus snd_pcm
[ 85.811559] inv_mpu6050_i2c inv_mpu6050 tpm_tis snd_timer tpm_tis_core industrialio_triggered_buffer thermal snd kfifo_buf tpm ecdh_generic cm3218x i2c_mux rtc_cmos intel_int0002_vgpio soc_button_array button industrialio acpi_pad ac soundcore battery hid_asus asus_wmi rfkill usbhid hid_multitouch mmc_block i915 i2c_algo_bit drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops xhci_pci drm xhci_hcd wmi video i2c_hid sdhci_acpi sdhci mmc_core 8250_dw sg dm_multipath dm_mod dax efivarfs
[ 85.811674] CPU: 1 PID: 7 Comm: kworker/u8:0 Tainted: G W 5.1.0-rrh-t100-1 #1
[ 85.811680] Hardware name: ASUSTeK COMPUTER INC. T100TA/T100TA, BIOS T100TA.307 05/09/2014
[ 85.811695] Workqueue: events_unbound async_run_entry_fn
[ 85.811712] RIP: 0010:i2c_dw_xfer+0x95/0x277
[ 85.811723] Code: 05 fa c1 c0 00 01 48 8b 6f 50 48 85 ed 75 04 48 8b 6f 10 e8 c9 13 f4 ff 48 89 ea 48 89 c6 48 c7 c7 a5 0b ec 81 e8 74 19 b8 ff <0f> 0b bd 94 ff ff ff e9 ae 01 00 00 48 89 6b 68 c7 43 18 00 00 00
[ 85.811731] RSP: 0000:ffffc9000007f778 EFLAGS: 00010282
[ 85.811741] RAX: 0000000000000000 RBX: ffff8880761f4818 RCX: 0000000000000007
[ 85.811748] RDX: 0000000000000000 RSI: ffff8880766954f0 RDI: ffff8880766954f0
[ 85.811755] RBP: ffff8880761b49e0 R08: 00000000000002c9 R09: 0000000000000001
[ 85.811761] R10: 0000000000000000 R11: 0000001cd45f1266 R12: 0000000000000002
[ 85.811768] R13: ffff8880761f48c8 R14: 0000000000000000 R15: 00000000fffca615
[ 85.811778] FS: 0000000000000000(0000) GS:ffff888076680000(0000) knlGS:0000000000000000
[ 85.811785] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 85.811792] CR2: 0000561e75e8bee6 CR3: 0000000067bfa000 CR4: 00000000001006e0
[ 85.811797] Call Trace:
[ 85.811820] __i2c_transfer+0x289/0x393
[ 85.811836] i2c_smbus_xfer_emulated+0x3f0/0x58b
[ 85.811851] ? __i2c_transfer+0x289/0x393
[ 85.811868] ? acpi_ut_trace+0x1d/0x59
[ 85.811882] ? __i2c_smbus_xfer+0x162/0x2e3
[ 85.811894] __i2c_smbus_xfer+0x162/0x2e3
[ 85.811910] i2c_smbus_xfer+0x51/0x79
[ 85.811924] i2c_smbus_read_byte_data+0x3b/0x5f
[ 85.811940] i2c_acpi_space_handler+0x127/0x3ef
[ 85.811957] ? up+0x28/0x35
[ 85.811976] ? acpi_ev_address_space_dispatch+0x2d9/0x37b
[ 85.811989] acpi_ev_address_space_dispatch+0x2d9/0x37b
[ 85.812003] ? kzalloc.constprop.8+0xa/0xa
[ 85.812018] acpi_ex_access_region+0x434/0x4d3
[ 85.812032] ? acpi_ut_create_buffer_object+0x75/0xf3
[ 85.812045] ? acpi_ut_trace+0x1d/0x59
[ 85.812059] acpi_ex_read_serial_bus+0x1a2/0x1f7
[ 85.812075] acpi_ex_read_data_from_field+0xef/0x32b
[ 85.812090] acpi_ex_resolve_node_to_value+0x394/0x4c9
[ 85.812105] acpi_ex_resolve_to_value+0x3b4/0x461
[ 85.812121] acpi_ds_evaluate_name_path+0xa8/0x161
[ 85.812136] ? acpi_db_single_step+0x15/0x251
[ 85.812150] acpi_ds_exec_end_op+0x118/0x74e
[ 85.812165] acpi_ps_parse_loop+0x7ca/0x88c
[ 85.812180] acpi_ps_parse_aml+0x1a6/0x542
[ 85.812195] acpi_ps_execute_method+0x1fc/0x2b8
[ 85.812211] acpi_ns_evaluate+0x33c/0x4cf
[ 85.812224] acpi_evaluate_object+0x1c6/0x389
[ 85.812243] acpi_dev_pm_explicit_set+0x51/0x75
[ 85.812258] acpi_device_set_power+0x1a8/0x257
[ 85.812276] acpi_pci_set_power_state+0x81/0xc3
[ 85.812294] pci_power_up+0x27/0x3c
[ 85.812310] pci_pm_default_resume_early+0x9/0x27
[ 85.812325] pci_pm_resume_noirq+0x40/0xa5
[ 85.812340] ? pci_pm_thaw_noirq+0x9a/0x9a
[ 85.812353] dpm_run_callback+0x5e/0xb6
[ 85.812369] ? pci_pm_thaw_noirq+0x9a/0x9a
[ 85.812381] device_resume_noirq+0x142/0x198
[ 85.812396] async_resume_noirq+0x14/0x38
[ 85.812410] async_run_entry_fn+0x68/0x126
[ 85.812427] process_one_work+0x19b/0x298
[ 85.812443] ? create_worker+0x16d/0x16d
[ 85.812455] worker_thread+0x18c/0x237
[ 85.812470] kthread+0xe6/0xeb
[ 85.812484] ? kthread_create_worker_on_cpu+0x61/0x61
[ 85.812498] ret_from_fork+0x35/0x40
[ 85.812514] ---[ end trace a3057465d1745352 ]---
[ 86.088989] ACPI: button: The lid device is not compliant to SW_LID.
[ 86.544221] OOM killer enabled.
[ 86.544258] Restarting tasks ... done.
[ 86.584199] PM: suspend exit
[ 94.039596] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[ 112.693492] PM: suspend entry (s2idle)
[ 112.693496] PM: Syncing filesystems ... done.
[ 114.076883] Freezing user space processes ... (elapsed 0.002 seconds) done.
[ 114.079637] OOM killer disabled.
[ 114.079639] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
[ 115.681852] OOM killer enabled.
[ 115.681857] Restarting tasks ... done.
[ 115.714314] PM: suspend exit
[ 123.010931] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[ 138.483287] PM: suspend entry (s2idle)
[ 138.483292] PM: Syncing filesystems ... done.
[ 139.690315] Freezing user space processes ... (elapsed 0.002 seconds) done.
[ 139.693025] OOM killer disabled.
[ 139.693027] Freezing remaining freezable tasks ... (elapsed 0.000 seconds) done.
[ 144.796368] OOM killer enabled.
[ 144.796385] Restarting tasks ... done.
[ 144.831840] PM: suspend exit
[ 152.112181] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[ 162.780110] PM: suspend entry (s2idle)
[ 162.780115] PM: Syncing filesystems ... done.
[ 163.456370] Freezing user space processes ... (elapsed 0.002 seconds) done.
[ 163.458911] OOM killer disabled.
[ 163.458913] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
[ 165.434909] OOM killer enabled.
[ 165.434917] Restarting tasks ... done.
[ 165.472053] PM: suspend exit
[ 172.702385] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready