r8169 delay / segfault

Hi,

on a Samsung laptop (x86_64, kernel 3.6.0), I get the following messages in the kernel log after a suspend/resume cycle (doesn't happen after every suspend/resume but sometimes):

Oct 12 21:02:27 darwin kernel: [ 4289.829755] r8169 0000:02:00.0: wake-up capability disabled by ACPI
Oct 12 21:02:27 darwin kernel: [ 4289.830351] r8169 0000:02:00.0: eth0: rtl_phyar_cond == 1 (loop: 20, delay: 25).
Oct 12 21:02:27 darwin kernel: [ 4289.831077] r8169 0000:02:00.0: eth0: rtl_phyar_cond == 1 (loop: 20, delay: 25).
Oct 12 21:02:27 darwin kernel: [ 4289.831671] r8169 0000:02:00.0: eth0: rtl_phyar_cond == 1 (loop: 20, delay: 25).
Oct 12 21:02:27 darwin kernel: [ 4289.832214] r8169 0000:02:00.0: eth0: rtl_phyar_cond == 1 (loop: 20, delay: 25).
Oct 12 21:02:27 darwin kernel: [ 4289.832757] r8169 0000:02:00.0: eth0: rtl_phyar_cond == 1 (loop: 20, delay: 25).
Oct 12 21:02:27 darwin kernel: [ 4289.833303] r8169 0000:02:00.0: eth0: rtl_phyar_cond == 1 (loop: 20, delay: 25).
Oct 12 21:02:27 darwin kernel: [ 4289.834885] r8169 0000:02:00.0: eth0: rtl_phyar_cond == 1 (loop: 20, delay: 25).
Oct 12 21:02:27 darwin kernel: [ 4289.835429] r8169 0000:02:00.0: eth0: rtl_phyar_cond == 1 (loop: 20, delay: 25).
Oct 12 21:02:27 darwin kernel: [ 4289.835972] r8169 0000:02:00.0: eth0: rtl_phyar_cond == 1 (loop: 20, delay: 25).
Oct 12 21:02:27 darwin kernel: [ 4289.836518] r8169 0000:02:00.0: eth0: rtl_phyar_cond == 1 (loop: 20, delay: 25).
Oct 12 21:02:27 darwin kernel: [ 4289.857820] r8169 0000:02:00.0: eth0: rtl_phyar_cond == 1 (loop: 20, delay: 25).
Oct 12 21:02:27 darwin kernel: [ 4289.858371] r8169 0000:02:00.0: eth0: rtl_phyar_cond == 1 (loop: 20, delay: 25).
Oct 12 21:02:27 darwin kernel: [ 4289.858920] r8169 0000:02:00.0: eth0: rtl_phyar_cond == 1 (loop: 20, delay: 25).

[...]

Oct 12 21:04:38 darwin kernel: [ 4422.635491] r8169 0000:02:00.0: eth0: rtl_eriar_cond == 1 (loop: 100, delay: 100).
Oct 12 21:04:38 darwin kernel: [ 4422.635499] r8169 0000:02:00.0: eth0: link up
Oct 12 21:04:56 darwin kernel: [ 4441.319712] ------------[ cut here ]------------
Oct 12 21:04:56 darwin kernel: [ 4441.319733] WARNING: at net/sched/sch_generic.c:255 dev_watchdog+0xe3/0x153()
Oct 12 21:04:56 darwin kernel: [ 4441.319737] Hardware name: 900X3C/900X4C/900X4D
Oct 12 21:04:56 darwin kernel: [ 4441.319741] NETDEV WATCHDOG: eth0 (r8169): transmit queue 0 timed out
Oct 12 21:04:56 darwin kernel: [ 4441.319744] Modules linked in: nf_conntrack_ipv6 nf_defrag_ipv6 xt_LOG xt_limit xt_tcpudp nf_conntrack_ipv4 nf_defrag_ipv4 x

t_state nf_conntrack_ftp xt_conntrack nf_conntrack ip6table_filter ip6_tables iptable_filter ip_tables ebtable_nat ebtables x_tables parport_pc ppdev lp parpo rt bnep rfcomm binfmt_misc uinput nfsd auth_rpcgss nfs_acl nfs lockd fscache sunrpc loop fuse snd_hda_codec_hdmi snd_hda_codec_realtek joydev arc4 coretemp kv m_intel kvm btusb iwldvm bluetooth crc32c_intel mac80211 ghash_clmulni_intel iTCO_wdt iTCO_vendor_support aesni_intel aes_x86_64 snd_hda_intel snd_hda_codec s nd_hwdep snd_pcm aes_generic ablk_helper snd_page_alloc cryptd snd_seq snd_timer snd_seq_device samsung_laptop evdev snd iwlwifi i915 microcode drm_kms_helper
drm soundcore psmouse pcspkr cfg80211 i2c_i801 lpc_ich i2c_algo_bit serio_raw mfd_core rfkill i2c_core battery acpi_cpufreq mperf wmi video ac button process
or ext4 crc16 jbd2 mbcache dm_mod sg sd_mod crc_t10dif ehci_hcd xhci_hcd fan th

Oct 12 21:04:56 darwin kernel: ermal ahci thermal_sys libahci usbcore r8169 mii usb_common libata scsi_mod
Oct 12 21:04:56 darwin kernel: [ 4441.319903] Pid: 0, comm: swapper/1 Not tainted 3.6.0 #1
Oct 12 21:04:56 darwin kernel: [ 4441.319906] Call Trace:
Oct 12 21:04:56 darwin kernel: [ 4441.319910]  <IRQ>  [<ffffffff8103c914>] ? warn_slowpath_common+0x76/0x8a
Oct 12 21:04:56 darwin kernel: [ 4441.319932]  [<ffffffff8103c9c0>] ? warn_slowpath_fmt+0x45/0x4a
Oct 12 21:04:56 darwin kernel: [ 4441.319941]  [<ffffffff812b9b62>] ? netif_tx_lock+0x67/0x7a
Oct 12 21:04:56 darwin kernel: [ 4441.319954]  [<ffffffff812b9c58>] ? dev_watchdog+0xe3/0x153
Oct 12 21:04:56 darwin kernel: [ 4441.319963]  [<ffffffff810492e1>] ? run_timer_softirq+0x19f/0x2b0
Oct 12 21:04:56 darwin kernel: [ 4441.319974]  [<ffffffff81068208>] ? trigger_load_balance+0x50/0x1df
Oct 12 21:04:56 darwin kernel: [ 4441.319980]  [<ffffffff812b9b75>] ? netif_tx_lock+0x7a/0x7a
Oct 12 21:04:56 darwin kernel: [ 4441.319989]  [<ffffffff811b8320>] ? timerqueue_add+0x80/0xa0
Oct 12 21:04:56 darwin kernel: [ 4441.319998]  [<ffffffff8104332f>] ? __do_softirq+0xac/0x1d1
Oct 12 21:04:56 darwin kernel: [ 4441.320007]  [<ffffffff81073706>] ? ktime_get+0x62/0x6a
Oct 12 21:04:56 darwin kernel: [ 4441.320015]  [<ffffffff81078109>] ? clockevents_program_event+0x9a/0xb6
Oct 12 21:04:56 darwin kernel: [ 4441.320025]  [<ffffffff81367ebc>] ? call_softirq+0x1c/0x30
Oct 12 21:04:56 darwin kernel: [ 4441.320036]  [<ffffffff8100f8fe>] ? do_softirq+0x3a/0x78
Oct 12 21:04:56 darwin kernel: [ 4441.320043]  [<ffffffff81043611>] ? irq_exit+0x3a/0x91
Oct 12 21:04:56 darwin kernel: [ 4441.320052]  [<ffffffff8102845c>] ? smp_apic_timer_interrupt+0x74/0x82
Oct 12 21:04:56 darwin kernel: [ 4441.320060]  [<ffffffff813677ca>] ? apic_timer_interrupt+0x6a/0x70
Oct 12 21:04:56 darwin kernel: [ 4441.320062]  <EOI>  [<ffffffff81078109>] ? clockevents_program_event+0x9a/0xb6
Oct 12 21:04:56 darwin kernel: [ 4441.320077]  [<ffffffff811f8174>] ? intel_idle+0xdf/0x10a
Oct 12 21:04:56 darwin kernel: [ 4441.320084]  [<ffffffff811f814f>] ? intel_idle+0xba/0x10a
Oct 12 21:04:56 darwin kernel: [ 4441.320094]  [<ffffffff812810b3>] ? cpuidle_enter_state+0xa/0x31
Oct 12 21:04:56 darwin kernel: [ 4441.320100]  [<ffffffff812811a7>] ? cpuidle_idle_call+0xcd/0x184
Oct 12 21:04:56 darwin kernel: [ 4441.320107]  [<ffffffff81014f30>] ? cpu_idle+0x9c/0xe6
Oct 12 21:04:56 darwin kernel: [ 4441.320117]  [<ffffffff81353e4f>] ? start_secondary+0x1d2/0x1d8
Oct 12 21:04:56 darwin kernel: [ 4441.320122] ---[ end trace 2ae2e4a392ef84b6 ]---
Oct 12 21:04:56 darwin kernel: [ 4441.330385] r8169 0000:02:00.0: eth0: rtl_chipcmd_cond == 1 (loop: 100, delay: 100).
Oct 12 21:04:56 darwin kernel: [ 4441.331592] r8169 0000:02:00.0: eth0: rtl_csiar_cond == 1 (loop: 100, delay: 10).
Oct 12 21:04:56 darwin kernel: [ 4441.332727] r8169 0000:02:00.0: eth0: rtl_ephyar_cond == 1 (loop: 100, delay: 10).
Oct 12 21:04:56 darwin kernel: [ 4441.333866] r8169 0000:02:00.0: eth0: rtl_ephyar_cond == 1 (loop: 100, delay: 10).
Oct 12 21:04:56 darwin kernel: [ 4441.343912] r8169 0000:02:00.0: eth0: rtl_eriar_cond == 1 (loop: 100, delay: 100).
Oct 12 21:04:56 darwin kernel: [ 4441.353943] r8169 0000:02:00.0: eth0: rtl_eriar_cond == 1 (loop: 100, delay: 100).
Oct 12 21:04:56 darwin kernel: [ 4441.363973] r8169 0000:02:00.0: eth0: rtl_eriar_cond == 1 (loop: 100, delay: 100).
Oct 12 21:04:56 darwin kernel: [ 4441.374003] r8169 0000:02:00.0: eth0: rtl_eriar_cond == 1 (loop: 100, delay: 100).
Oct 12 21:04:56 darwin kernel: [ 4441.384034] r8169 0000:02:00.0: eth0: rtl_eriar_cond == 1 (loop: 100, delay: 100).
Oct 12 21:04:56 darwin kernel: [ 4441.394065] r8169 0000:02:00.0: eth0: rtl_eriar_cond == 1 (loop: 100, delay: 100).
Oct 12 21:04:56 darwin kernel: [ 4441.404196] r8169 0000:02:00.0: eth0: rtl_eriar_cond == 1 (loop: 100, delay: 100).
Oct 12 21:04:56 darwin kernel: [ 4441.414334] r8169 0000:02:00.0: eth0: rtl_eriar_cond == 1 (loop: 100, delay: 100).
Oct 12 21:04:56 darwin kernel: [ 4441.424383] r8169 0000:02:00.0: eth0: rtl_eriar_cond == 1 (loop: 100, delay: 100).
Oct 12 21:04:56 darwin kernel: [ 4441.434412] r8169 0000:02:00.0: eth0: rtl_eriar_cond == 1 (loop: 100, delay: 100).
Oct 12 21:04:56 darwin kernel: [ 4441.444546] r8169 0000:02:00.0: eth0: rtl_eriar_cond == 1 (loop: 100, delay: 100).
Oct 12 21:04:56 darwin kernel: [ 4441.454683] r8169 0000:02:00.0: eth0: rtl_eriar_cond == 1 (loop: 100, delay: 100).
Oct 12 21:04:56 darwin kernel: [ 4441.454689] r8169 0000:02:00.0: eth0: link up

I copied a bigger part of the kernel log at http://antcom.de/kernel/dmesg.

Please tell me how I can help debugging or what else information you need.

Thanks in advance,

Roland

Roland Stigge <[email protected]> :
[...]

[...]

[...]

[...]

The device seems completely unresponsive :o/

The device does not recover despite the "link up" message, right ?

Can you send the XID line from the r8169 driver ? It should be in the upper part of the dmesg log.

Which kernel version did you previously use ?

Ueimor

Hi!

Right.

Oct 12 23:46:45 darwin kernel: [    1.562479] r8169 Gigabit Ethernet driver 2.3LK-NAPI loaded
Oct 12 23:46:45 darwin kernel: [    1.562728] r8169 0000:02:00.0: irq 40 for MSI/MSI-X
Oct 12 23:46:45 darwin kernel: [    1.562968] r8169 0000:02:00.0: eth0: RTL8168evl/8111evl at 0xffffc9000066c000, e8:03:9a:dc:e7:57, XID 0c900800 IRQ 40
Oct 12 23:46:45 darwin kernel: [    1.562972] r8169 0000:02:00.0: eth0: jumbo features [frames: 9200 bytes, tx checksumming: ko]

I used the Debian standard kernel 3.2 but had several spontaneous crashes. Memtests and everything work fine. After upgrading, everything works but network sometimes breaks after suspend/resume (although "link up" is reported). Seems quite reproducible.

Roland

Hi,

Additional info: After reloading the driver after the failed state, I get:

[ 2454.524089] r8169 Gigabit Ethernet driver 2.3LK-NAPI loaded
[ 2454.537300] r8169 0000:02:00.0: Refused to change power state, currently in D3
[ 2454.537334] r8169 0000:02:00.0: cache line size of 64 is not supported
[ 2454.537342] r8169 0000:02:00.0: (unregistered net_device): Mem-Wr-Inval unavailable
[ 2454.537425] r8169 0000:02:00.0: (unregistered net_device): unknown MAC, using family default
[ 2454.547513] r8169 0000:02:00.0: (unregistered net_device): rtl_chipcmd_cond == 1 (loop: 100, delay: 100).
[ 2454.548092] r8169 0000:02:00.0: eth0: RTL8168b/8111b at 0xffffc9000066c000, ff:ff:ff:ff:ff:ff, XID 9cf0f8ff IRQ 19
[ 2454.548103] r8169 0000:02:00.0: eth0: jumbo features [frames: 4080 bytes, tx checksumming: ko]

What does the different device ID, XID and IRQ number mean? How can we force the device out of D3 power state?

I also compared with kernel 3.5, and it seems like a regression to me, With 3.5, it works and tells on resume:

[   37.643061] Extended CMOS year: 2000
[   37.644466] ACPI: Low-level resume complete
[   37.644516] PM: Restoring platform NVS memory
[   37.644901] Extended CMOS year: 2000
[   37.644944] Enabling non-boot CPUs ...
[   37.645127] Booting Node 0 Processor 1 APIC 0x1
[   37.659483] CPU1 is up
[   37.659662] Booting Node 0 Processor 2 APIC 0x2
[   37.673887] CPU2 is up
[   37.674060] Booting Node 0 Processor 3 APIC 0x3
[   37.688354] CPU3 is up
[   37.693255] ACPI: Waking up from system sleep state S3
[   37.742293] PM: noirq resume of devices complete after 1.725 msecs
[   37.742392] PM: early resume of devices complete after 0.050 msecs
[   37.742421] i915 0000:00:02.0: >setting latency timer to 64
[   37.742445] ehci_hcd 0000:00:1d.0: >setting latency timer to 64
[   37.742484] ata_piix 0000:00:1f.2: >setting latency timer to 64
[   37.742496] snd_hda_intel 0000:00:1b.0: >irq 48 for MSI/MSI-X
[   37.743872] ata_piix 0000:00:1f.5: >setting latency timer to 64
[   37.743887] r8169 0000:02:00.0: >wake-up capability disabled by ACPI
[   37.743972] ata1.00: _GTF evaluation failed (AE 0x1001)
[   37.789378] [drm] Enabling RC6 states: RC6 on, RC6p on, RC6pp off
[   37.825318] r8169 0000:02:00.0: >eth0: link down
[   37.992301] usb 1-1.6: >reset high-speed USB device number 4 using ehci_hcd
[   38.327824] usb 1-1.5: >reset full-speed USB device number 3 using ehci_hcd
[   38.422689] btusb 1-1.5:1.0: >no reset_resume for driver btusb?
[   38.422691] btusb 1-1.5:1.1: >no reset_resume for driver btusb?
[   38.766989] ata2.00: failed to resume link (SControl 30)
[   39.086505] ata1.01: failed to resume link (SControl 0)
[   39.242350] ata1.00: SATA link up 6.0 Gbps (SStatus 133 SControl 330)
[   39.242362] ata1.01: SATA link down (SStatus 0 SControl 0)
[   39.258694] ata1.00: configured for UDMA/133
[   39.258925] sd 0:0:0:0: >[sda] Starting disk
[   39.793487] ata2.01: failed to resume link (SControl 0)
[   39.804987] ata2.00: SATA link down (SStatus 4 SControl 30)
[   39.805001] ata2.01: SATA link down (SStatus 0 SControl 0)
[   39.805211] PM: resume of devices complete after 2065.886 msecs
[   39.805431] PM: Finishing wakeup.
[   39.805432] Restarting tasks ... done.

Thanks in advance,

Roland

Roland Stigge <[email protected]> :
[...]

XID identifies the chipset. If the chipset stops responding - all 1 bits - the device can not be identified.

Can you try both a 3.5 kernel with the 3.6 r8169 driver and a 3.6 kernel with the 3.5 r8169 driver ?

Ueimor

Sorry for the delay.

What makes the whole thing difficult is that on vanilla 3.6, the problem happens always, while with vanilla 3.5 it also happens but much less often - about every 10th suspend / resume cycle.

To test the 3.5 r8169 driver with a 3.6 kernel, and vice versa, I copied over the r8169.c file, respectively.

The result is that the 3.6 kernel with the "old" driver shows the same issue as the vanilla 3.6. On 3.5 I also see the same thing happen as before - every 10th suspend / resume cycle the problem happens, independent of the "old" or "new" driver.

So the difference comes from the kernel, but finally it is present anyway. Maybe it is just triggered more efficiently in 3.6? ;-)

Remember that I don't encountered problems with other drivers' suspend/resume, only with the r8169.

Thanks for considering. Please tell me how I can help further on this issue.

Roland