Re: 4.16-rc3 fails to resume on MacBookPro10,1 -

From: Pavel Machek
Date: Sun Mar 11 2018 - 06:34:36 EST

Hi!

> >> This is 4.15 kernel with KPTI disabled:
> >> % grep PAGE_TABLE .config
> >> # CONFIG_PAGE_TABLE_ISOLATION is not set
> >>
> >> As I expected it appears no more infomative to me.
> >>
> >> What I really need is some clue as to what is supposed to be happening
> >> at this point.
> >
> > You may want to add some printks to see where it hangs.
> >
> > But maybe before that, you may want to test CPU hotplug, and make sure
> > s2ram works, etc...
> >
> > Perhaps basic-pm-debugging.txt is good place to start?
> >
> > Best regards,
> > Pavel
> > --
>
> Ok - all the test modes work but a full s2ram hangs (never comes back)
> and obviously the resume full save to disk fails.
>
> I attach the following files:
>
> echo reboot > /sys/power/disk
> echo disk > /sys/power/state
> Then saved dmesg to file dmesg-reboot-disk-ok.txt

So with "reboot" mode, hibernation works as expected, you just have to
power down machine manually?

> I tried to add some debug to hibernation_restore() but saw nothing.
> Not sure if I doing this correctly but I believe the last know dmesg
> entry is from swsusp_read() in kernel/power/swap.c
> but then I should see something in hibernation_restore() but as the
> console might not work or something I can't be sure....
>
> Further directions appreciated

You may want to try without thunderbolt support / talk to thunderbolt
people:

pciehp seems to have bad problems, too.

I'd suggest debugging with s2ram (as it is less tricky) and removing
all modules you don't really need.

Good luck,
Pavel

> [ 340.781428] calling 0000:04:00.0+ @ 2273, parent: 0000:00:1c.1
> [ 340.781430] calling 0000:03:00.1+ @ 2292, parent: 0000:00:1c.0
> [ 340.781431] calling 0000:03:00.0+ @ 2217, parent: 0000:00:1c.0
> [ 340.781435] calling 0000:07:00.0+ @ 2207, parent: 0000:06:00.0
> [ 340.781439] calling 0000:06:06.0+ @ 2197, parent: 0000:05:00.0
> [ 340.781441] thunderbolt 0000:07:00.0: suspending...
> [ 340.781446] ------------[ cut here ]------------
> [ 340.781448] tb_cfg_write: -108
> [ 340.781454] calling PNP0C09:00+ @ 2337, parent: device:2c
> [ 340.781456] call PNP0C09:00+ returned 0 after 0 usecs
> [ 340.781486] WARNING: CPU: 3 PID: 2207 at drivers/thunderbolt/ctl.c:981 tb_cfg_write+0x6f/0xd0 [thunderbolt]
> [ 340.781487] calling 0000:06:05.0+ @ 2202, parent: 0000:05:00.0
> [ 340.781488] calling 0000:06:04.0+ @ 2291, parent: 0000:05:00.0
> [ 340.781494] Modules linked in: ebtable_filter ebtables ip6table_filter ip6_tables hidp xt_addrtype xt_conntrack ipt_MASQUERADE nf_nat_masquerade_ipv4 iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack bridge stp llc ppdev parport_pc parport dm_thin_pool dm_persistent_data dm_bio_prison dm_bufio fuse vmw_vsock_vmci_transport vsock dm_mod vmw_vmci iptable_filter cmac bnep intel_rapl x86_pkg_temp_thermal intel_powerclamp snd_hda_codec_hdmi binfmt_misc nls_ascii nls_cp437 coretemp arc4 b43 kvm_intel vfat fat kvm irqbypass crct10dif_pclmul crc32_pclmul mac80211 ghash_clmulni_intel pcbc ssb mmc_core aesni_intel rng_core aes_x86_64 crypto_simd pcmcia iTCO_wdt glue_helper iTCO_vendor_support cryptd r8188eu(C) pcmcia_core uvcvideo btusb btrtl btbcm btintel videobuf2_vmalloc snd_hda_codec_cirrus
> [ 340.781541] snd_hda_codec_generic bluetooth videobuf2_memops intel_cstate videobuf2_v4l2 drbg videobuf2_core applesmc ansi_cprng snd_hda_intel videodev cfg80211 ecdh_generic input_polldev intel_uncore joydev rfkill media intel_rapl_perf snd_hda_codec sbs sg bcma snd_hda_core thunderbolt acpi_als snd_hwdep sbshc kfifo_buf snd_pcm industrialio apple_gmux mei_me lpc_ich snd_timer shpchp mei snd mfd_core evdev soundcore apple_bl pcspkr ac efi_pstore nfsd auth_rpcgss nfs_acl lockd grace sunrpc efivars loop efivarfs ip_tables x_tables autofs4 hid_apple ext4 crc16 mbcache jbd2 fscrypto btrfs zstd_decompress zstd_compress xxhash raid10 raid456 async_raid6_recov async_memcpy async_pq async_xor async_tx xor hid_generic usbhid hid raid6_pq libcrc32c crc32c_generic raid1 raid0 multipath linear md_mod bcm5974
> [ 340.781593] ax88179_178a usbnet mii sd_mod nouveau ahci libahci mxm_wmi xhci_pci i915 libata wmi crc32c_intel ehci_pci xhci_hcd ttm i2c_algo_bit ehci_hcd scsi_mod i2c_i801 drm_kms_helper usbcore drm video button
> [ 340.781610] CPU: 3 PID: 2207 Comm: kworker/u16:95 Tainted: G WC 4.15.0+ #9
> [ 340.781612] Hardware name: Apple Inc. MacBookPro10,1/Mac-C3EC7CD22292981F, BIOS MBP101.88Z.00EE.B0A.1509111559 09/11/2015
> [ 340.781618] Workqueue: events_unbound async_run_entry_fn
> [ 340.781623] RIP: 0010:tb_cfg_write+0x6f/0xd0 [thunderbolt]
> [ 340.781625] RSP: 0018:ffffb8a383a43d00 EFLAGS: 00010286
> [ 340.781627] RAX: 0000000000000000 RBX: ffff964cd317da80 RCX: 0000000000000006
> [ 340.781630] RDX: 0000000000000007 RSI: 0000000000000086 RDI: ffff964cef2d66b0
> [ 340.781633] RBP: 0000000000000002 R08: 0000000000000000 R09: 0000000000001011
> [ 340.781635] R10: ffffffffb726fe40 R11: ffff964cd428dc00 R12: 0000000000000004
> [ 340.781637] R13: ffff964cdcbdc000 R14: 0000000000000004 R15: ffffffffb74767a4
> [ 340.781640] FS: 0000000000000000(0000) GS:ffff964cef2c0000(0000) knlGS:0000000000000000
> [ 340.781642] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 340.781644] CR2: 00007f1aae263f80 CR3: 000000035dc09003 CR4: 00000000001606e0
> [ 340.781647] Call Trace:
> [ 340.781655] tb_plug_events_active+0x8e/0x180 [thunderbolt]
> [ 340.781660] tb_switch_suspend+0x11/0x90 [thunderbolt]
> [ 340.781665] tb_suspend_noirq+0x33/0x60 [thunderbolt]
> [ 340.781671] tb_domain_suspend_noirq+0x30/0x70 [thunderbolt]
> [ 340.781674] pci_pm_suspend_noirq+0x79/0x190
> [ 340.781677] ? pci_pm_resume_noirq+0x90/0x90
> [ 340.781680] dpm_run_callback+0x4d/0x140
> [ 340.781683] __device_suspend_noirq+0x7f/0x160
> [ 340.781686] async_suspend_noirq+0x1a/0x90
> [ 340.781688] async_run_entry_fn+0x33/0x160
> [ 340.781692] process_one_work+0x184/0x380
> [ 340.781695] worker_thread+0x4d/0x3c0
> [ 340.781698] kthread+0xf5/0x130
> [ 340.781701] ? process_one_work+0x380/0x380
> [ 340.781703] ? kthread_create_worker_on_cpu+0x70/0x70
> [ 340.781706] ret_from_fork+0x35/0x40
> [ 340.781709] Code: 24 18 e8 45 fc ff ff 8b 44 24 24 48 83 c4 18 85 c0 74 1e 83 f8 01 74 57 83 f8 92 74 2d 89 c6 48 c7 c7 26 db db c0 e8 31 54 8c f5 <0f> ff 8b 44 24 0c 48 8b 5c 24 18 65 48 33 1c 25 28 00 00 00 75
> [ 340.781737] ---[ end trace d61e276b076455e3 ]---
> [ 340.781766] thunderbolt 0000:07:00.0: suspend finished
> [ 340.781772] thunderbolt 0000:07:00.0: stopping RX ring 0
> [ 340.781800] thunderbolt 0000:07:00.0: stopping TX ring 0
...
> [ 346.427262] calling 0000:07:00.0+ @ 2217, parent: 0000:06:00.0
> [ 346.427266] thunderbolt 0000:07:00.0: Refused to change power state, currently in D3
> [ 346.427275] thunderbolt 0000:07:00.0: control channel starting...
> [ 346.427280] thunderbolt 0000:07:00.0: resuming...
> [ 346.427284] thunderbolt 0000:07:00.0: resetting switch at 0
> [ 346.427291] ------------[ cut here ]------------
> [ 346.427292] tb_cfg_write: -108
> [ 346.427333] WARNING: CPU: 7 PID: 2217 at drivers/thunderbolt/ctl.c:981 tb_cfg_write+0x6f/0xd0 [thunderbolt]
> [ 346.427337] Modules linked in: ebtable_filter ebtables ip6table_filter ip6_tables hidp xt_addrtype xt_conntrack ipt_MASQUERADE nf_nat_masquerade_ipv4 iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack bridge stp llc ppdev parport_pc parport dm_thin_pool dm_persistent_data dm_bio_prison dm_bufio fuse vmw_vsock_vmci_transport vsock dm_mod vmw_vmci iptable_filter cmac bnep intel_rapl x86_pkg_temp_thermal intel_powerclamp snd_hda_codec_hdmi binfmt_misc nls_ascii nls_cp437 coretemp arc4 b43 kvm_intel vfat fat kvm irqbypass crct10dif_pclmul crc32_pclmul mac80211 ghash_clmulni_intel pcbc ssb mmc_core aesni_intel rng_core aes_x86_64 crypto_simd pcmcia iTCO_wdt glue_helper iTCO_vendor_support cryptd r8188eu(C) pcmcia_core uvcvideo btusb btrtl btbcm btintel videobuf2_vmalloc snd_hda_codec_cirrus
> [ 346.427388] snd_hda_codec_generic bluetooth videobuf2_memops intel_cstate videobuf2_v4l2 drbg videobuf2_core applesmc ansi_cprng snd_hda_intel videodev cfg80211 ecdh_generic input_polldev intel_uncore joydev rfkill media intel_rapl_perf snd_hda_codec sbs sg bcma snd_hda_core thunderbolt acpi_als snd_hwdep sbshc kfifo_buf snd_pcm industrialio apple_gmux mei_me lpc_ich snd_timer shpchp mei snd mfd_core evdev soundcore apple_bl pcspkr ac efi_pstore nfsd auth_rpcgss nfs_acl lockd grace sunrpc efivars loop efivarfs ip_tables x_tables autofs4 hid_apple ext4 crc16 mbcache jbd2 fscrypto btrfs zstd_decompress zstd_compress xxhash raid10 raid456 async_raid6_recov async_memcpy async_pq async_xor async_tx xor hid_generic usbhid hid raid6_pq libcrc32c crc32c_generic raid1 raid0 multipath linear md_mod bcm5974
> [ 346.427440] ax88179_178a usbnet mii sd_mod nouveau ahci libahci mxm_wmi xhci_pci i915 libata wmi crc32c_intel ehci_pci xhci_hcd ttm i2c_algo_bit ehci_hcd scsi_mod i2c_i801 drm_kms_helper usbcore drm video button
> [ 346.427459] CPU: 7 PID: 2217 Comm: kworker/u16:105 Tainted: G WC 4.15.0+ #9
> [ 346.427461] Hardware name: Apple Inc. MacBookPro10,1/Mac-C3EC7CD22292981F, BIOS MBP101.88Z.00EE.B0A.1509111559 09/11/2015
> [ 346.427467] Workqueue: events_unbound async_run_entry_fn
> [ 346.427473] RIP: 0010:tb_cfg_write+0x6f/0xd0 [thunderbolt]
> [ 346.427475] RSP: 0000:ffffb8a383a93d18 EFLAGS: 00010286
> [ 346.427478] RAX: 0000000000000000 RBX: ffff964cd317da80 RCX: 0000000000000006
> [ 346.427480] RDX: 0000000000000007 RSI: 0000000000000096 RDI: ffff964cef3d66b0
> [ 346.427482] RBP: 0000000000000002 R08: 0000000000000000 R09: 00000000000010c7
> [ 346.427484] R10: ffffffffb726fe40 R11: ffff964cd428dc00 R12: 0000000000000002
> [ 346.427487] R13: 00000050a5e920bb R14: 0000000000000010 R15: ffffffffb74767a4
> [ 346.427489] FS: 0000000000000000(0000) GS:ffff964cef3c0000(0000) knlGS:0000000000000000
> [ 346.427492] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 346.427494] CR2: 0000000000000000 CR3: 000000035dc09001 CR4: 00000000001606e0
> [ 346.427496] Call Trace:
> [ 346.427505] tb_switch_reset+0xa6/0xf0 [thunderbolt]
> [ 346.427510] tb_resume_noirq+0x3c/0x100 [thunderbolt]
> [ 346.427516] tb_domain_resume_noirq+0x3f/0x60 [thunderbolt]
> [ 346.427520] ? pci_pm_freeze_noirq+0xe0/0xe0
> [ 346.427522] dpm_run_callback+0x4d/0x140
> [ 346.427526] device_resume_noirq+0x84/0x140
> [ 346.427528] async_resume_noirq+0x19/0x40
> [ 346.427531] async_run_entry_fn+0x33/0x160
> [ 346.427535] process_one_work+0x184/0x380
> [ 346.427538] worker_thread+0x4d/0x3c0
> [ 346.427541] kthread+0xf5/0x130
> [ 346.427544] ? process_one_work+0x380/0x380
> [ 346.427546] ? kthread_create_worker_on_cpu+0x70/0x70
> [ 346.427551] ret_from_fork+0x35/0x40
> [ 346.427553] Code: 24 18 e8 45 fc ff ff 8b 44 24 24 48 83 c4 18 85 c0 74 1e 83 f8 01 74 57 83 f8 92 74 2d 89 c6 48 c7 c7 26 db db c0 e8 31 54 8c f5 <0f> ff 8b 44 24 0c 48 8b 5c 24 18 65 48 33 1c 25 28 00 00 00 75
> [ 346.427582] ---[ end trace d61e276b076455e4 ]---
> [ 346.427586] thunderbolt 0000:07:00.0: 0: resuming switch
> [ 346.427589] ------------[ cut here ]------------
> [ 346.427591] tb_cfg_write: -108
> [ 346.427606] WARNING: CPU: 7 PID: 2217 at drivers/thunderbolt/ctl.c:981 tb_cfg_write+0x6f/0xd0 [thunderbolt]
> [ 346.427608] Modules linked in: ebtable_filter ebtables ip6table_filter ip6_tables hidp xt_addrtype xt_conntrack ipt_MASQUERADE nf_nat_masquerade_ipv4 iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack bridge stp llc ppdev parport_pc parport dm_thin_pool dm_persistent_data dm_bio_prison dm_bufio fuse vmw_vsock_vmci_transport vsock dm_mod vmw_vmci iptable_filter cmac bnep intel_rapl x86_pkg_temp_thermal intel_powerclamp snd_hda_codec_hdmi binfmt_misc nls_ascii nls_cp437 coretemp arc4 b43 kvm_intel vfat fat kvm irqbypass crct10dif_pclmul crc32_pclmul mac80211 ghash_clmulni_intel pcbc ssb mmc_core aesni_intel rng_core aes_x86_64 crypto_simd pcmcia iTCO_wdt glue_helper iTCO_vendor_support cryptd r8188eu(C) pcmcia_core uvcvideo btusb btrtl btbcm btintel videobuf2_vmalloc snd_hda_codec_cirrus
> [ 346.427645] snd_hda_codec_generic bluetooth videobuf2_memops intel_cstate videobuf2_v4l2 drbg videobuf2_core applesmc ansi_cprng snd_hda_intel videodev cfg80211 ecdh_generic input_polldev intel_uncore joydev rfkill media intel_rapl_perf snd_hda_codec sbs sg bcma snd_hda_core thunderbolt acpi_als snd_hwdep sbshc kfifo_buf snd_pcm industrialio apple_gmux mei_me lpc_ich snd_timer shpchp mei snd mfd_core evdev soundcore apple_bl pcspkr ac efi_pstore nfsd auth_rpcgss nfs_acl lockd grace sunrpc efivars loop efivarfs ip_tables x_tables autofs4 hid_apple ext4 crc16 mbcache jbd2 fscrypto btrfs zstd_decompress zstd_compress xxhash raid10 raid456 async_raid6_recov async_memcpy async_pq async_xor async_tx xor hid_generic usbhid hid raid6_pq libcrc32c crc32c_generic raid1 raid0 multipath linear md_mod bcm5974
> [ 346.427686] ax88179_178a usbnet mii sd_mod nouveau ahci libahci mxm_wmi xhci_pci i915 libata wmi crc32c_intel ehci_pci xhci_hcd ttm i2c_algo_bit ehci_hcd scsi_mod i2c_i801 drm_kms_helper usbcore drm video button
> [ 346.427699] CPU: 7 PID: 2217 Comm: kworker/u16:105 Tainted: G WC 4.15.0+ #9
> [ 346.427701] Hardware name: Apple Inc. MacBookPro10,1/Mac-C3EC7CD22292981F, BIOS MBP101.88Z.00EE.B0A.1509111559 09/11/2015
> [ 346.427705] Workqueue: events_unbound async_run_entry_fn
> [ 346.427710] RIP: 0010:tb_cfg_write+0x6f/0xd0 [thunderbolt]
> [ 346.427712] RSP: 0000:ffffb8a383a93d28 EFLAGS: 00010286
> [ 346.427714] RAX: 0000000000000000 RBX: ffff964cd317da80 RCX: 0000000000000006
> [ 346.427716] RDX: 0000000000000007 RSI: 0000000000000096 RDI: ffff964cef3d66b0
> [ 346.427718] RBP: 0000000000000002 R08: 0000000000000000 R09: 00000000000010ec
> [ 346.427721] R10: ffffffffb726fe40 R11: ffff964cd428dc00 R12: 0000000000000001
> [ 346.427723] R13: 00000050a5e920bb R14: 0000000000000010 R15: ffffffffb74767a4
> [ 346.427725] FS: 0000000000000000(0000) GS:ffff964cef3c0000(0000) knlGS:0000000000000000
> [ 346.427728] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 346.427730] CR2: 0000000000000000 CR3: 000000035dc09001 CR4: 00000000001606e0
> [ 346.427731] Call Trace:
> [ 346.427737] tb_switch_resume+0x139/0x290 [thunderbolt]
> [ 346.427742] tb_resume_noirq+0x49/0x100 [thunderbolt]
> [ 346.427747] tb_domain_resume_noirq+0x3f/0x60 [thunderbolt]
> [ 346.427750] ? pci_pm_freeze_noirq+0xe0/0xe0
> [ 346.427752] dpm_run_callback+0x4d/0x140
> [ 346.427755] device_resume_noirq+0x84/0x140
> [ 346.427757] async_resume_noirq+0x19/0x40
> [ 346.427760] async_run_entry_fn+0x33/0x160
> [ 346.427763] process_one_work+0x184/0x380
> [ 346.427766] worker_thread+0x4d/0x3c0
> [ 346.427768] kthread+0xf5/0x130
> [ 346.427771] ? process_one_work+0x380/0x380
> [ 346.427773] ? kthread_create_worker_on_cpu+0x70/0x70
> [ 346.427777] ret_from_fork+0x35/0x40
> [ 346.427779] Code: 24 18 e8 45 fc ff ff 8b 44 24 24 48 83 c4 18 85 c0 74 1e 83 f8 01 74 57 83 f8 92 74 2d 89 c6 48 c7 c7 26 db db c0 e8 31 54 8c f5 <0f> ff 8b 44 24 0c 48 8b 5c 24 18 65 48 33 1c 25 28 00 00 00 75
> [ 346.427807] ---[ end trace d61e276b076455e5 ]---
> [ 346.427810] thunderbolt 0000:07:00.0: resume finished
> [ 346.427813] call 0000:07:00.0+ returned 0 after 536 usecs
> [ 346.427821] call 0000:06:03.0+ returned 0 after 838 usecs
> [ 346.427822] call 0000:06:05.0+ returned 0 after 837 usecs
> [ 346.427823] call 0000:06:06.0+ returned 0 after 834 usecs
> [ 346.427824] call 0000:06:04.0+ returned 0 after 836 usecs
> [ 346.446729] call 0000:00:1d.0+ returned 0 after 19516 usecs
...
> [ 346.470407] calling hdaudioC0D0+ @ 2165, parent: 0000:00:1b.0
> [ 346.470412] calling hdaudioC1D0+ @ 2175, parent: 0000:01:00.1
> [ 346.472524] call hdaudioC0D0+ returned 0 after 2061 usecs
> [ 346.474383] pciehp 0000:06:05.0:pcie204: Timeout on hotplug command 0x1038 (issued 129884 msec ago)
> [ 346.474387] pciehp 0000:06:06.0:pcie204: Timeout on hotplug command 0x1038 (issued 129884 msec ago)
> [ 346.474389] pciehp 0000:06:03.0:pcie204: Timeout on hotplug command 0x1038 (issued 129888 msec ago)
> [ 346.474392] pciehp 0000:06:06.0:pcie204: pcie_do_write_cmd: no response from device
> [ 346.474393] pciehp 0000:06:03.0:pcie204: pcie_do_write_cmd: no response from device
> [ 346.474400] pciehp 0000:06:04.0:pcie204: Timeout on hotplug command 0x1038 (issued 129884 msec ago)
> [ 346.474402] pciehp 0000:06:04.0:pcie204: pcie_do_write_cmd: no response from device
> [ 346.474408] pciehp 0000:06:05.0:pcie204: pcie_do_write_cmd: no response from device
> [ 346.525712] call usb1+ returned 0 after 56999 usecs
> [ 346.525766] calling 1-1+ @ 2278, parent: usb1
> [ 346.525870] call usb3+ returned 0 after 57106 usecs
> [ 346.525922] calling 3-2+ @ 2215, parent: usb3
> [ 346.525925] calling 3-1+ @ 2187, parent: usb3
> [ 346.526820] call 1-1+ returned 0 after 1014 usecs
> [ 346.526847] calling 1-1.1+ @ 2208, parent: 1-1
> [ 346.530426] call hdaudioC1D0+ returned 0 after 58591 usecs
> [ 346.600377] call 1-1.1+ returned 0 after 71789 usecs
> [ 346.638929] call 3-2+ returned 0 after 110327 usecs
> [ 346.642430] call 2-1+ returned 0 after 170735 usecs
> [ 346.642485] calling 2-1.8+ @ 2173, parent: 2-1
> [ 346.722446] usb 2-1.8: reset high-speed USB device number 3 using ehci-pci
> [ 346.780813] ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
> [ 346.781322] ata1.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
> [ 346.784817] ata1.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
> [ 346.787041] ata1.00: configured for UDMA/133
> [ 346.894759] MAC Address = c4:e9:84:14:1a:0e
> [ 346.896225] call 3-1+ returned 0 after 361566 usecs
> [ 347.046573] call 2-1.8+ returned 0 after 394549 usecs
> [ 347.046615] calling 2-1.8.2+ @ 2183, parent: 2-1.8
> [ 347.046637] calling 2-1.8.1+ @ 2269, parent: 2-1.8
> [ 347.126563] usb 2-1.8.2: reset full-speed USB device number 5 using ehci-pci
> [ 347.243290] call 2-1.8.2+ returned 0 after 192029 usecs
> [ 347.314579] usb 2-1.8.1: reset full-speed USB device number 4 using ehci-pci
> [ 347.638630] call 2-1.8.1+ returned 0 after 578022 usecs
> [ 347.638698] calling 2-1.8.1.3+ @ 2123, parent: 2-1.8.1
> [ 347.718642] usb 2-1.8.1.3: reset full-speed USB device number 8 using ehci-pci
> [ 347.828460] call 2-1.8.1.3+ returned 0 after 185279 usecs
> [ 347.982658] pciehp 0000:06:05.0:pcie204: link training error: status 0xffff
> [ 347.982661] pciehp 0000:06:04.0:pcie204: link training error: status 0xffff
> [ 347.982666] pciehp 0000:06:03.0:pcie204: link training error: status 0xffff
> [ 347.982668] pciehp 0000:06:06.0:pcie204: link training error: status 0xffff
> [ 347.982673] pciehp 0000:06:04.0:pcie204: Failed to check link
> status
...
> [ 373.710654] calling 0000:03:00.0+ @ 2223, parent: 0000:00:1c.0
> [ 373.710657] calling 0000:07:00.0+ @ 2307, parent: 0000:06:00.0
> [ 373.710659] calling 0000:06:06.0+ @ 2150, parent: 0000:05:00.0
> [ 373.710661] thunderbolt 0000:07:00.0: suspending...
> [ 373.710663] calling 0000:06:05.0+ @ 2199, parent: 0000:05:00.0
> [ 373.710666] ------------[ cut here ]------------
> [ 373.710670] tb_cfg_write: -108
> [ 373.710684] calling PNP0C09:00+ @ 2367, parent: device:2c
> [ 373.710687] call PNP0C09:00+ returned 0 after 0 usecs
> [ 373.710704] calling 0000:06:04.0+ @ 2312, parent: 0000:05:00.0
> [ 373.710711] WARNING: CPU: 7 PID: 2307 at drivers/thunderbolt/ctl.c:981 tb_cfg_write+0x6f/0xd0 [thunderbolt]
> [ 373.710713] Modules linked in: ebtable_filter ebtables ip6table_filter ip6_tables hidp xt_addrtype xt_conntrack ipt_MASQUERADE nf_nat_masquerade_ipv4 iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack bridge stp llc ppdev parport_pc parport dm_thin_pool dm_persistent_data dm_bio_prison dm_bufio fuse vmw_vsock_vmci_transport vsock dm_mod vmw_vmci iptable_filter cmac bnep intel_rapl x86_pkg_temp_thermal intel_powerclamp snd_hda_codec_hdmi binfmt_misc nls_ascii nls_cp437 coretemp arc4 b43 kvm_intel vfat fat kvm irqbypass crct10dif_pclmul crc32_pclmul mac80211 ghash_clmulni_intel pcbc ssb mmc_core aesni_intel rng_core aes_x86_64 crypto_simd pcmcia iTCO_wdt glue_helper iTCO_vendor_support cryptd r8188eu(C) pcmcia_core uvcvideo btusb btrtl btbcm btintel videobuf2_vmalloc snd_hda_codec_cirrus
> [ 373.710760] snd_hda_codec_generic bluetooth videobuf2_memops intel_cstate videobuf2_v4l2 drbg videobuf2_core applesmc ansi_cprng snd_hda_intel videodev cfg80211 ecdh_generic input_polldev intel_uncore joydev rfkill media intel_rapl_perf snd_hda_codec sbs sg bcma snd_hda_core thunderbolt acpi_als snd_hwdep sbshc kfifo_buf snd_pcm industrialio apple_gmux mei_me lpc_ich snd_timer shpchp mei snd mfd_core evdev soundcore apple_bl pcspkr ac efi_pstore nfsd auth_rpcgss nfs_acl lockd grace sunrpc efivars loop efivarfs ip_tables x_tables autofs4 hid_apple ext4 crc16 mbcache jbd2 fscrypto btrfs zstd_decompress zstd_compress xxhash raid10 raid456 async_raid6_recov async_memcpy async_pq async_xor async_tx xor hid_generic usbhid hid raid6_pq libcrc32c crc32c_generic raid1 raid0 multipath linear md_mod bcm5974
> [ 373.710811] ax88179_178a usbnet mii sd_mod nouveau ahci libahci mxm_wmi xhci_pci i915 libata wmi crc32c_intel ehci_pci xhci_hcd ttm i2c_algo_bit ehci_hcd scsi_mod i2c_i801 drm_kms_helper usbcore drm video button
> [ 373.710829] CPU: 7 PID: 2307 Comm: kworker/u16:160 Tainted: G WC 4.15.0+ #9
> [ 373.710832] Hardware name: Apple Inc. MacBookPro10,1/Mac-C3EC7CD22292981F, BIOS MBP101.88Z.00EE.B0A.1509111559 09/11/2015
> [ 373.710838] Workqueue: events_unbound async_run_entry_fn
> [ 373.710844] RIP: 0010:tb_cfg_write+0x6f/0xd0 [thunderbolt]
> [ 373.710847] RSP: 0018:ffffb8a383c6bd00 EFLAGS: 00010286
> [ 373.710850] RAX: 0000000000000000 RBX: ffff964cd317da80 RCX: 0000000000000006
> [ 373.710852] RDX: 0000000000000007 RSI: 0000000000000086 RDI: ffff964cef3d66b0
> [ 373.710854] RBP: 0000000000000002 R08: 0000000000000000 R09: 000000000000136e
> [ 373.710857] R10: ffffffffb726fe40 R11: ffff964cd428dc00 R12: 0000000000000004
> [ 373.710859] R13: ffff964cdcbdc000 R14: 0000000000000004 R15: ffffffffb74767a4
> [ 373.710861] FS: 0000000000000000(0000) GS:ffff964cef3c0000(0000) knlGS:0000000000000000
> [ 373.710864] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 373.710866] CR2: 0000000000ad3208 CR3: 000000035dc09001 CR4: 00000000001606e0
> [ 373.710868] Call Trace:
> [ 373.710876] tb_plug_events_active+0x8e/0x180 [thunderbolt]
> [ 373.710882] tb_switch_suspend+0x11/0x90 [thunderbolt]
> [ 373.710886] tb_suspend_noirq+0x33/0x60 [thunderbolt]
> [ 373.710892] tb_domain_suspend_noirq+0x30/0x70 [thunderbolt]
> [ 373.710895] pci_pm_suspend_noirq+0x79/0x190
> [ 373.710898] ? pci_pm_resume_noirq+0x90/0x90
> [ 373.710901] dpm_run_callback+0x4d/0x140
> [ 373.710903] __device_suspend_noirq+0x7f/0x160
> [ 373.710906] async_suspend_noirq+0x1a/0x90
> [ 373.710908] async_run_entry_fn+0x33/0x160
> [ 373.710912] process_one_work+0x184/0x380
> [ 373.710915] worker_thread+0x4d/0x3c0
> [ 373.710918] kthread+0xf5/0x130
> [ 373.710920] ? process_one_work+0x380/0x380
> [ 373.710923] ? kthread_create_worker_on_cpu+0x70/0x70
> [ 373.710927] ret_from_fork+0x35/0x40
> [ 373.710930] Code: 24 18 e8 45 fc ff ff 8b 44 24 24 48 83 c4 18 85 c0 74 1e 83 f8 01 74 57 83 f8 92 74 2d 89 c6 48 c7 c7 26 db db c0 e8 31 54 8c f5 <0f> ff 8b 44 24 0c 48 8b 5c 24 18 65 48 33 1c 25 28 00 00 00 75
> [ 373.710956] ---[ end trace d61e276b076455e6 ]---
> [ 373.710966] thunderbolt 0000:07:00.0: suspend finished
> [ 373.710973] thunderbolt 0000:07:00.0: stopping RX ring 0
> [ 373.710996] thunderbolt 0000:07:00.0: stopping TX ring 0
> [ 373.711017] thunderbolt 0000:07:00.0: control channel stopped
> [ 373.711025] call 0000:07:00.0+ returned 0 after 358 usecs
...
> [ 379.355848] thunderbolt 0000:07:00.0: Refused to change power state, currently in D3
> [ 379.355853] thunderbolt 0000:07:00.0: control channel starting...
> [ 379.355868] thunderbolt 0000:07:00.0: resuming...
> [ 379.355870] thunderbolt 0000:07:00.0: resetting switch at 0
> [ 379.355877] ------------[ cut here ]------------
> [ 379.355880] tb_cfg_write: -108
> [ 379.355921] WARNING: CPU: 7 PID: 2122 at drivers/thunderbolt/ctl.c:981 tb_cfg_write+0x6f/0xd0 [thunderbolt]
> [ 379.355924] Modules linked in: ebtable_filter ebtables ip6table_filter ip6_tables hidp xt_addrtype xt_conntrack ipt_MASQUERADE nf_nat_masquerade_ipv4 iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack bridge stp llc ppdev parport_pc parport dm_thin_pool dm_persistent_data dm_bio_prison dm_bufio fuse vmw_vsock_vmci_transport vsock dm_mod vmw_vmci iptable_filter cmac bnep intel_rapl x86_pkg_temp_thermal intel_powerclamp snd_hda_codec_hdmi binfmt_misc nls_ascii nls_cp437 coretemp arc4 b43 kvm_intel vfat fat kvm irqbypass crct10dif_pclmul crc32_pclmul mac80211 ghash_clmulni_intel pcbc ssb mmc_core aesni_intel rng_core aes_x86_64 crypto_simd pcmcia iTCO_wdt glue_helper iTCO_vendor_support cryptd r8188eu(C) pcmcia_core uvcvideo btusb btrtl btbcm btintel videobuf2_vmalloc snd_hda_codec_cirrus
> [ 379.355975] snd_hda_codec_generic bluetooth videobuf2_memops intel_cstate videobuf2_v4l2 drbg videobuf2_core applesmc ansi_cprng snd_hda_intel videodev cfg80211 ecdh_generic input_polldev intel_uncore joydev rfkill media intel_rapl_perf snd_hda_codec sbs sg bcma snd_hda_core thunderbolt acpi_als snd_hwdep sbshc kfifo_buf snd_pcm industrialio apple_gmux mei_me lpc_ich snd_timer shpchp mei snd mfd_core evdev soundcore apple_bl pcspkr ac efi_pstore nfsd auth_rpcgss nfs_acl lockd grace sunrpc efivars loop efivarfs ip_tables x_tables autofs4 hid_apple ext4 crc16 mbcache jbd2 fscrypto btrfs zstd_decompress zstd_compress xxhash raid10 raid456 async_raid6_recov async_memcpy async_pq async_xor async_tx xor hid_generic usbhid hid raid6_pq libcrc32c crc32c_generic raid1 raid0 multipath linear md_mod bcm5974
> [ 379.356035] ax88179_178a usbnet mii sd_mod nouveau ahci libahci mxm_wmi xhci_pci i915 libata wmi crc32c_intel ehci_pci xhci_hcd ttm i2c_algo_bit ehci_hcd scsi_mod i2c_i801 drm_kms_helper usbcore drm video button
> [ 379.356057] CPU: 7 PID: 2122 Comm: kworker/u16:11 Tainted: G WC 4.15.0+ #9
> [ 379.356060] Hardware name: Apple Inc. MacBookPro10,1/Mac-C3EC7CD22292981F, BIOS MBP101.88Z.00EE.B0A.1509111559 09/11/2015
> [ 379.356066] Workqueue: events_unbound async_run_entry_fn
> [ 379.356073] RIP: 0010:tb_cfg_write+0x6f/0xd0 [thunderbolt]
> [ 379.356076] RSP: 0000:ffffb8a3837f3d18 EFLAGS: 00010286
> [ 379.356079] RAX: 0000000000000000 RBX: ffff964cd317da80 RCX: 0000000000000006
> [ 379.356081] RDX: 0000000000000007 RSI: 0000000000000096 RDI: ffff964cef3d66b0
> [ 379.356084] RBP: 0000000000000002 R08: 0000000000000000 R09: 0000000000001437
> [ 379.356086] R10: ffffffffb726fe40 R11: ffff964cd428dc00 R12: 0000000000000002
> [ 379.356089] R13: 0000005728b1bf09 R14: 0000000000000010 R15: ffffffffb74767a4
> [ 379.356092] FS: 0000000000000000(0000) GS:ffff964cef3c0000(0000) knlGS:0000000000000000
> [ 379.356095] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 379.356097] CR2: 0000000000000000 CR3: 000000035dc09001 CR4: 00000000001606e0
> [ 379.356100] Call Trace:
> [ 379.356110] tb_switch_reset+0xa6/0xf0 [thunderbolt]
> [ 379.356116] tb_resume_noirq+0x3c/0x100 [thunderbolt]
> [ 379.356122] tb_domain_resume_noirq+0x3f/0x60 [thunderbolt]
> [ 379.356127] ? pci_pm_freeze_noirq+0xe0/0xe0
> [ 379.356130] dpm_run_callback+0x4d/0x140
> [ 379.356134] device_resume_noirq+0x84/0x140
> [ 379.356137] async_resume_noirq+0x19/0x40
> [ 379.356140] async_run_entry_fn+0x33/0x160
> [ 379.356145] process_one_work+0x184/0x380
> [ 379.356149] worker_thread+0x4d/0x3c0
> [ 379.356152] kthread+0xf5/0x130
> [ 379.356155] ? process_one_work+0x380/0x380
> [ 379.356158] ? kthread_create_worker_on_cpu+0x70/0x70
> [ 379.356163] ret_from_fork+0x35/0x40
> [ 379.356167] Code: 24 18 e8 45 fc ff ff 8b 44 24 24 48 83 c4 18 85 c0 74 1e 83 f8 01 74 57 83 f8 92 74 2d 89 c6 48 c7 c7 26 db db c0 e8 31 54 8c f5 <0f> ff 8b 44 24 0c 48 8b 5c 24 18 65 48 33 1c 25 28 00 00 00 75
> [ 379.356201] ---[ end trace d61e276b076455e7 ]---
> [ 379.356204] thunderbolt 0000:07:00.0: 0: resuming switch
> [ 379.356208] ------------[ cut here ]------------
> [ 379.356210] tb_cfg_write: -108
> [ 379.356227] WARNING: CPU: 7 PID: 2122 at drivers/thunderbolt/ctl.c:981 tb_cfg_write+0x6f/0xd0 [thunderbolt]
> [ 379.356230] Modules linked in: ebtable_filter ebtables ip6table_filter ip6_tables hidp xt_addrtype xt_conntrack ipt_MASQUERADE nf_nat_masquerade_ipv4 iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack bridge stp llc ppdev parport_pc parport dm_thin_pool dm_persistent_data dm_bio_prison dm_bufio fuse vmw_vsock_vmci_transport vsock dm_mod vmw_vmci iptable_filter cmac bnep intel_rapl x86_pkg_temp_thermal intel_powerclamp snd_hda_codec_hdmi binfmt_misc nls_ascii nls_cp437 coretemp arc4 b43 kvm_intel vfat fat kvm irqbypass crct10dif_pclmul crc32_pclmul mac80211 ghash_clmulni_intel pcbc ssb mmc_core aesni_intel rng_core aes_x86_64 crypto_simd pcmcia iTCO_wdt glue_helper iTCO_vendor_support cryptd r8188eu(C) pcmcia_core uvcvideo btusb btrtl btbcm btintel videobuf2_vmalloc snd_hda_codec_cirrus
> [ 379.356273] snd_hda_codec_generic bluetooth videobuf2_memops intel_cstate videobuf2_v4l2 drbg videobuf2_core applesmc ansi_cprng snd_hda_intel videodev cfg80211 ecdh_generic input_polldev intel_uncore joydev rfkill media intel_rapl_perf snd_hda_codec sbs sg bcma snd_hda_core thunderbolt acpi_als snd_hwdep sbshc kfifo_buf snd_pcm industrialio apple_gmux mei_me lpc_ich snd_timer shpchp mei snd mfd_core evdev soundcore apple_bl pcspkr ac efi_pstore nfsd auth_rpcgss nfs_acl lockd grace sunrpc efivars loop efivarfs ip_tables x_tables autofs4 hid_apple ext4 crc16 mbcache jbd2 fscrypto btrfs zstd_decompress zstd_compress xxhash raid10 raid456 async_raid6_recov async_memcpy async_pq async_xor async_tx xor hid_generic usbhid hid raid6_pq libcrc32c crc32c_generic raid1 raid0 multipath linear md_mod bcm5974
> [ 379.356320] ax88179_178a usbnet mii sd_mod nouveau ahci libahci mxm_wmi xhci_pci i915 libata wmi crc32c_intel ehci_pci xhci_hcd ttm i2c_algo_bit ehci_hcd scsi_mod i2c_i801 drm_kms_helper usbcore drm video button
> [ 379.356336] CPU: 7 PID: 2122 Comm: kworker/u16:11 Tainted: G WC 4.15.0+ #9
> [ 379.356338] Hardware name: Apple Inc. MacBookPro10,1/Mac-C3EC7CD22292981F, BIOS MBP101.88Z.00EE.B0A.1509111559 09/11/2015
> [ 379.356343] Workqueue: events_unbound async_run_entry_fn
> [ 379.356349] RIP: 0010:tb_cfg_write+0x6f/0xd0 [thunderbolt]
> [ 379.356351] RSP: 0000:ffffb8a3837f3d28 EFLAGS: 00010286
> [ 379.356354] RAX: 0000000000000000 RBX: ffff964cd317da80 RCX: 0000000000000006
> [ 379.356356] RDX: 0000000000000007 RSI: 0000000000000096 RDI: ffff964cef3d66b0
> [ 379.356359] RBP: 0000000000000002 R08: 0000000000000000 R09: 000000000000145c
> [ 379.356361] R10: ffffffffb726fe40 R11: ffff964cd428dc00 R12: 0000000000000001
> [ 379.356364] R13: 0000005728b1bf09 R14: 0000000000000010 R15: ffffffffb74767a4
> [ 379.356367] FS: 0000000000000000(0000) GS:ffff964cef3c0000(0000) knlGS:0000000000000000
> [ 379.356369] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 379.356372] CR2: 0000000000000000 CR3: 000000035dc09001 CR4: 00000000001606e0
> [ 379.356374] Call Trace:
> [ 379.356380] tb_switch_resume+0x139/0x290 [thunderbolt]
> [ 379.356386] tb_resume_noirq+0x49/0x100 [thunderbolt]
> [ 379.356392] tb_domain_resume_noirq+0x3f/0x60 [thunderbolt]
> [ 379.356395] ? pci_pm_freeze_noirq+0xe0/0xe0
> [ 379.356398] dpm_run_callback+0x4d/0x140
> [ 379.356401] device_resume_noirq+0x84/0x140
> [ 379.356403] async_resume_noirq+0x19/0x40
> [ 379.356407] async_run_entry_fn+0x33/0x160
> [ 379.356410] process_one_work+0x184/0x380
> [ 379.356413] worker_thread+0x4d/0x3c0
> [ 379.356416] kthread+0xf5/0x130
> [ 379.356420] ? process_one_work+0x380/0x380
> [ 379.356422] ? kthread_create_worker_on_cpu+0x70/0x70
> [ 379.356426] ret_from_fork+0x35/0x40
> [ 379.356429] Code: 24 18 e8 45 fc ff ff 8b 44 24 24 48 83 c4 18 85 c0 74 1e 83 f8 01 74 57 83 f8 92 74 2d 89 c6 48 c7 c7 26 db db c0 e8 31 54 8c f5 <0f> ff 8b 44 24 0c 48 8b 5c 24 18 65 48 33 1c 25 28 00 00 00 75
> [ 379.356462] ---[ end trace d61e276b076455e8 ]---
> [ 379.356466] thunderbolt 0000:07:00.0: resume finished
> [ 379.356468] call 0000:07:00.0+ returned 0 after 607 usecs
> [ 379.356480] call 0000:06:05.0+ returned 0 after 899 usecs


--
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

Attachment: signature.asc
Description: Digital signature