found 656331 3.2.2-1
quit


Dear Linux folks,


Am Mittwoch, den 18.01.2012, 15:50 +0000 schrieb Ben Hutchings:
> On Wed, 2012-01-18 at 16:32 +0100, Paul Menzel wrote:
> > Am Mittwoch, den 18.01.2012, 15:03 +0000 schrieb Ben Hutchings:
> > > On Wed, 2012-01-18 at 15:15 +0100, Paul Menzel wrote:
> > > > Package: linux-2.6
> > > > Version: 3.1.8-2
> > > > Severity: normal
> >
> > > > suspending and resuming a lot, it happens once to me, that the network
> > > > device did not come back correctly.

I experienced this problem (only) three times until now. If I remember
correctly the last time with 3.2.1. I still do not know how to reproduce
this.

The work around is to unplug and replug the network cable or to unload
the module and load it again.

> > > [...]
> > >
> > > Some of the RTL81xx gigabit Ethernet controllers need a firmware patch
> > > to be reliable. I can't tell whether you have one of these. Are there
> > > any kernel log messages about requesting a firmware file for the NIC?
> > > If so, does installing firmware-realtek fix the problem?
> >
> > There are no Linux messages requesting the firmware.
>
> OK.
>
> > And not being able
> > to trigger I probably just have to wait that it happens again. Can I
> > increase some log level to capture more information next time? Or since
> > this could be a firmware bug Linux cannot do anything about this?
>
> No, it's probably something that can be fixed in the driver.

That sounds promising. It would be great if this could be fixed. Please
tell me how I can get you better debugging information next time this
happens.

> > $ dmesg | grep -i firmware
> > $ dmesg | grep 8169
> > [ 1.109369] r8169 Gigabit Ethernet driver 2.3LK-NAPI loaded
> > [ 1.109417] r8169 0000:02:00.0: PCI INT A -> GSI 19 (level, low) -> IRQ 19
> > [ 1.109452] r8169 0000:02:00.0: setting latency timer to 64
> > [ 1.109511] r8169 0000:02:00.0: irq 41 for MSI/MSI-X
> > [ 1.110094] r8169 0000:02:00.0: eth0: RTL8168b/8111b at 0xffffc90000364000, 00:1e:8c:aa:1d:b5, XID 18000000 IRQ 41
> [...]
>
> Right, this variant doesn't need a firmware patch.
>
> Please can you re-send your bug report to:

[…]

> Be sure to include the log messages from your second mail.

Please find the messages from the Linux kernel ring buffer (`dmesg`)
attached at the end.


Thanks,

Paul


[1] http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=656331


$ dmesg | grep -i firmware
$ dmesg | grep 8169
[ 1.109369] r8169 Gigabit Ethernet driver 2.3LK-NAPI loaded
[ 1.109417] r8169 0000:02:00.0: PCI INT A -> GSI 19 (level, low) -> IRQ 19
[ 1.109452] r8169 0000:02:00.0: setting latency timer to 64
[ 1.109511] r8169 0000:02:00.0: irq 41 for MSI/MSI-X
[ 1.110094] r8169 0000:02:00.0: eth0: RTL8168b/8111b at 0xffffc90000364000, 00:1e:8c:aa:1d:b5, XID 18000000 IRQ 41
[ 299.062777] r8169 0000:02:00.0: eth0: link down
[ 300.770805] r8169 0000:02:00.0: eth0: link up
[ 3287.250629] r8169 0000:02:00.0: PME# enabled
[ 3287.397826] r8169 0000:02:00.0: restoring config space at offset 0xf (was 0x100, writing 0x10a)
[ 3287.397841] r8169 0000:02:00.0: restoring config space at offset 0x6 (was 0x4, writing 0xfdfff004)
[ 3287.397848] r8169 0000:02:00.0: restoring config space at offset 0x4 (was 0x1, writing 0xdc01)
[ 3287.397853] r8169 0000:02:00.0: restoring config space at offset 0x3 (was 0x0, writing 0x8)
[ 3287.397860] r8169 0000:02:00.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100407)
[ 3287.398443] r8169 0000:02:00.0: PME# disabled
[ 3314.429403] r8169 0000:02:00.0: eth0: link down
[ 3314.429432] r8169 0000:02:00.0: eth0: link down
[ 3316.043306] r8169 0000:02:00.0: eth0: link up
[ 4821.512812] r8169 0000:02:00.0: PME# enabled
[ 4821.661948] r8169 0000:02:00.0: restoring config space at offset 0xf (was 0x100, writing 0x10a)
[ 4821.661963] r8169 0000:02:00.0: restoring config space at offset 0x6 (was 0x4, writing 0xfdfff004)
[ 4821.661969] r8169 0000:02:00.0: restoring config space at offset 0x4 (was 0x1, writing 0xdc01)
[ 4821.661975] r8169 0000:02:00.0: restoring config space at offset 0x3 (was 0x0, writing 0x8)
[ 4821.661981] r8169 0000:02:00.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100407)
[ 4821.662532] r8169 0000:02:00.0: PME# disabled
[ 4839.563375] r8169 0000:02:00.0: eth0: link down
[ 4839.563398] r8169 0000:02:00.0: eth0: link down
[ 4841.198305] r8169 0000:02:00.0: eth0: link up
[ 7732.802716] r8169 0000:02:00.0: PME# enabled
[ 7732.910146] r8169 0000:02:00.0: restoring config space at offset 0xf (was 0x100, writing 0x10a)
[ 7732.910161] r8169 0000:02:00.0: restoring config space at offset 0x6 (was 0x4, writing 0xfdfff004)
[ 7732.910168] r8169 0000:02:00.0: restoring config space at offset 0x4 (was 0x1, writing 0xdc01)
[ 7732.910173] r8169 0000:02:00.0: restoring config space at offset 0x3 (was 0x0, writing 0x8)
[ 7732.910180] r8169 0000:02:00.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100407)
[ 7732.910733] r8169 0000:02:00.0: PME# disabled
[ 7761.865970] r8169 0000:02:00.0: eth0: link down
[ 7761.865984] r8169 0000:02:00.0: eth0: link down
[ 7763.542738] r8169 0000:02:00.0: eth0: link up
[15484.178593] r8169 0000:02:00.0: PME# enabled
[15484.346084] r8169 0000:02:00.0: restoring config space at offset 0xf (was 0x100, writing 0x10a)
[15484.346099] r8169 0000:02:00.0: restoring config space at offset 0x6 (was 0x4, writing 0xfdfff004)
[15484.346106] r8169 0000:02:00.0: restoring config space at offset 0x4 (was 0x1, writing 0xdc01)
[15484.346111] r8169 0000:02:00.0: restoring config space at offset 0x3 (was 0x0, writing 0x8)
[15484.346118] r8169 0000:02:00.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100407)
[15484.347428] r8169 0000:02:00.0: PME# disabled
[15510.394744] r8169 0000:02:00.0: eth0: link down
[15510.394763] r8169 0000:02:00.0: eth0: link down
[15512.071499] r8169 0000:02:00.0: eth0: link up
[18259.334467] r8169 0000:02:00.0: PME# enabled
[18259.501850] r8169 0000:02:00.0: restoring config space at offset 0xf (was 0x100, writing 0x10a)
[18259.501865] r8169 0000:02:00.0: restoring config space at offset 0x6 (was 0x4, writing 0xfdfff004)
[18259.501872] r8169 0000:02:00.0: restoring config space at offset 0x4 (was 0x1, writing 0xdc01)
[18259.501877] r8169 0000:02:00.0: restoring config space at offset 0x3 (was 0x0, writing 0x8)
[18259.501884] r8169 0000:02:00.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100407)
[18259.502438] r8169 0000:02:00.0: PME# disabled
[18278.302713] r8169 0000:02:00.0: eth0: link down
[18278.302745] r8169 0000:02:00.0: eth0: link down
[18280.011036] r8169 0000:02:00.0: eth0: link up
[25756.542579] r8169 0000:02:00.0: PME# enabled
[25756.603094] r8169 0000:02:00.0: restoring config space at offset 0xf (was 0x100, writing 0x10a)
[25756.603109] r8169 0000:02:00.0: restoring config space at offset 0x6 (was 0x4, writing 0xfdfff004)
[25756.603116] r8169 0000:02:00.0: restoring config space at offset 0x4 (was 0x1, writing 0xdc01)
[25756.603121] r8169 0000:02:00.0: restoring config space at offset 0x3 (was 0x0, writing 0x8)
[25756.603128] r8169 0000:02:00.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100407)
[25756.603748] r8169 0000:02:00.0: PME# disabled
[25777.623022] r8169 0000:02:00.0: eth0: link down
[25777.623051] r8169 0000:02:00.0: eth0: link down
[25779.226514] r8169 0000:02:00.0: eth0: link up
[31478.251100] r8169 0000:02:00.0: PME# enabled
[31478.421917] r8169 0000:02:00.0: restoring config space at offset 0xf (was 0x100, writing 0x10a)
[31478.421933] r8169 0000:02:00.0: restoring config space at offset 0x6 (was 0x4, writing 0xfdfff004)
[31478.421939] r8169 0000:02:00.0: restoring config space at offset 0x4 (was 0x1, writing 0xdc01)
[31478.421945] r8169 0000:02:00.0: restoring config space at offset 0x3 (was 0x0, writing 0x8)
[31478.421952] r8169 0000:02:00.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100407)
[31478.422570] r8169 0000:02:00.0: PME# disabled
[31503.383109] r8169 0000:02:00.0: eth0: link down
[31503.383136] r8169 0000:02:00.0: eth0: link down
[31505.007435] r8169 0000:02:00.0: eth0: link up
[38537.983241] r8169 0000:02:00.0: PME# enabled
[38538.137904] r8169 0000:02:00.0: restoring config space at offset 0xf (was 0x100, writing 0x10a)
[38538.137919] r8169 0000:02:00.0: restoring config space at offset 0x6 (was 0x4, writing 0xfdfff004)
[38538.137926] r8169 0000:02:00.0: restoring config space at offset 0x4 (was 0x1, writing 0xdc01)
[38538.137931] r8169 0000:02:00.0: restoring config space at offset 0x3 (was 0x0, writing 0x8)
[38538.137938] r8169 0000:02:00.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100407)
[38538.138558] r8169 0000:02:00.0: PME# disabled
[38561.350684] r8169 0000:02:00.0: eth0: link down
[38561.350695] r8169 0000:02:00.0: eth0: link down
[38563.006502] r8169 0000:02:00.0: eth0: link up
[55418.966878] r8169 0000:02:00.0: PME# enabled
[55419.198252] r8169 0000:02:00.0: restoring config space at offset 0xf (was 0x100, writing 0x10a)
[55419.198269] r8169 0000:02:00.0: restoring config space at offset 0x6 (was 0x4, writing 0xfdfff004)
[55419.198276] r8169 0000:02:00.0: restoring config space at offset 0x4 (was 0x1, writing 0xdc01)
[55419.198281] r8169 0000:02:00.0: restoring config space at offset 0x3 (was 0x0, writing 0x8)
[55419.198288] r8169 0000:02:00.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100407)
[55419.199056] r8169 0000:02:00.0: PME# disabled
[55463.662649] r8169 0000:02:00.0: eth0: link down
[55463.662669] r8169 0000:02:00.0: eth0: link down
[55579.968121] r8169 0000:02:00.0: eth0: link down
[55581.637656] r8169 0000:02:00.0: eth0: link up

# These two messages above came from the incident that I needed to replug the network cable.

[69238.835220] r8169 0000:02:00.0: PME# enabled
[69239.030058] r8169 0000:02:00.0: restoring config space at offset 0xf (was 0x100, writing 0x10a)
[69239.030073] r8169 0000:02:00.0: restoring config space at offset 0x6 (was 0x4, writing 0xfdfff004)
[69239.030079] r8169 0000:02:00.0: restoring config space at offset 0x4 (was 0x1, writing 0xdc01)
[69239.030085] r8169 0000:02:00.0: restoring config space at offset 0x3 (was 0x0, writing 0x8)
[69239.030091] r8169 0000:02:00.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100407)
[69239.030715] r8169 0000:02:00.0: PME# disabled
[69302.909251] r8169 0000:02:00.0: eth0: link down
[69302.909270] r8169 0000:02:00.0: eth0: link down
[69304.585998] r8169 0000:02:00.0: eth0: link up
[75793.819387] r8169 0000:02:00.0: PME# enabled
[75793.965963] r8169 0000:02:00.0: restoring config space at offset 0xf (was 0x100, writing 0x10a)
[75793.965979] r8169 0000:02:00.0: restoring config space at offset 0x6 (was 0x4, writing 0xfdfff004)
[75793.965986] r8169 0000:02:00.0: restoring config space at offset 0x4 (was 0x1, writing 0xdc01)
[75793.965992] r8169 0000:02:00.0: restoring config space at offset 0x3 (was 0x0, writing 0x8)
[75793.966000] r8169 0000:02:00.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100407)
[75793.966980] r8169 0000:02:00.0: PME# disabled
[75820.589236] r8169 0000:02:00.0: eth0: link down
[75820.589256] r8169 0000:02:00.0: eth0: link down
[75822.287067] r8169 0000:02:00.0: eth0: link up
[80551.485608] r8169 0000:02:00.0: PME# enabled
[80551.562098] r8169 0000:02:00.0: restoring config space at offset 0xf (was 0x100, writing 0x10a)
[80551.562114] r8169 0000:02:00.0: restoring config space at offset 0x6 (was 0x4, writing 0xfdfff004)
[80551.562122] r8169 0000:02:00.0: restoring config space at offset 0x4 (was 0x1, writing 0xdc01)
[80551.562128] r8169 0000:02:00.0: restoring config space at offset 0x3 (was 0x0, writing 0x8)
[80551.562135] r8169 0000:02:00.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100407)
[80551.563000] r8169 0000:02:00.0: PME# disabled
[80575.678825] r8169 0000:02:00.0: eth0: link down
[80575.678837] r8169 0000:02:00.0: eth0: link down
[80577.292704] r8169 0000:02:00.0: eth0: link up
[81125.015611] r8169 0000:02:00.0: PME# enabled
[81125.220938] r8169 0000:02:00.0: restoring config space at offset 0xf (was 0x100, writing 0x10a)
[81125.220955] r8169 0000:02:00.0: restoring config space at offset 0x6 (was 0x4, writing 0xfdfff004)
[81125.220962] r8169 0000:02:00.0: restoring config space at offset 0x4 (was 0x1, writing 0xdc01)
[81125.220968] r8169 0000:02:00.0: restoring config space at offset 0x3 (was 0x0, writing 0x8)
[81125.220976] r8169 0000:02:00.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100407)
[81125.221988] r8169 0000:02:00.0: PME# disabled
[81196.764877] r8169 0000:02:00.0: eth0: link down
[81196.764899] r8169 0000:02:00.0: eth0: link down
[81198.431155] r8169 0000:02:00.0: eth0: link up

Paul Menzel <pm.debian@googlemail.com> :
[http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=656331]
> I experienced this problem (only) three times until now. If I remember
> correctly the last time with 3.2.1. I still do not know how to reproduce
> this.

(good PR, nice)

An 'ethtool -d' and a 'mii-tool -v' of the device after a successful resume
and a failed one could help if it's a driver thing.

You may check if runtime power management is enabled or not, especially
after a failed resume. See the /sys/devices/pci....:../....:..:..../power
directory and its control, runtime_enabled and runtime_status files
(control = on -> runtime PM disabled, see Documentation/power/runtime_pm.txt)
If it is enabled and the link does not come up fast enough (5 s), runtime
PM will suspend the device. It should not matter as long as the link is
still present because the device should (TM) soon generate a power management
event. The latter not happening or the PME being ignored could explain
the bug. If so, temporarily disabling runtime PM for your device after a
failed resume instead of removing the module or the cable may be enough
to recover the link. It's just a guess though.

Please stay with v3.2 or above in the meantime.

--
Ueimor



--
To UNSUBSCRIBE, email to debian-kernel-REQUEST@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listmaster@lists.debian.org
Archive: 20120205175730.GA23604@electric-eye.fr.zoreil.com">http://lists.debian.org/20120205175730.GA23604@electric-eye.fr.zoreil.com

Dear Francois,


thank you for your fast reply.


Am Sonntag, den 05.02.2012, 18:57 +0100 schrieb Francois Romieu:
> Paul Menzel <pm.debian@googlemail.com> :
> [http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=656331]
> > I experienced this problem (only) three times until now. If I remember
> > correctly the last time with 3.2.1. I still do not know how to reproduce
> > this.
>
> (good PR, nice)
>
> An 'ethtool -d' and a 'mii-tool -v' of the device after a successful resume
> and a failed one could help if it's a driver thing.

The problem has not shown up again until now so I only send the output
from the successful resume. Currently Linux version 3.2.4 is installed.
The following outputs are identical after startup and (a successful)
resume.

$ sudo ethtool --version
ethtool version 3.1
$ sudo ethtool eth0 # The option `-d` does not exist.
Settings for eth0:
Supported ports: [ TP MII ]
Supported link modes: 10baseT/Half 10baseT/Full
100baseT/Half 100baseT/Full
1000baseT/Half 1000baseT/Full
Supported pause frame use: No
Supports auto-negotiation: Yes
Advertised link modes: 10baseT/Half 10baseT/Full
100baseT/Half 100baseT/Full
1000baseT/Half 1000baseT/Full
Advertised pause frame use: Symmetric Receive-only
Advertised auto-negotiation: Yes
Link partner advertised link modes: 10baseT/Half 10baseT/Full
100baseT/Half 100baseT/Full
Link partner advertised pause frame use: Symmetric
Link partner advertised auto-negotiation: Yes
Speed: 100Mb/s
Duplex: Full
Port: MII
PHYAD: 0
Transceiver: internal
Auto-negotiation: on
Supports Wake-on: pumbg
Wake-on: g
Current message level: 0x00000033 (51)
drv probe ifdown ifup
Link detected: yes

$ sudo mii-tool --version
$Id: mii-tool.c,v 1.9 2006/09/27 20:59:18 ecki Exp $
(Author: David Hinds based on Donald Becker's mii-diag)
net-tools 1.60
$ sudo mii-tool -v
eth0: negotiated 100baseTx-FD flow-control, link ok
product info: vendor 00:07:32, model 17 rev 2
basic mode: autonegotiation enabled
basic status: autonegotiation complete, link ok
capabilities: 1000baseT-HD 1000baseT-FD 100baseTx-FD 100baseTx-HD 10baseT-FD 10baseT-HD
advertising: 100baseTx-FD 100baseTx-HD 10baseT-FD 10baseT-HD flow-control
link partner: 1000baseT-HD 1000baseT-FD 100baseTx-FD 100baseTx-HD 10baseT-FD 10baseT-HD flow-control

> You may check if runtime power management is enabled or not, especially
> after a failed resume. See the /sys/devices/pci....:../....:..:..../power
> directory and its control, runtime_enabled and runtime_status files
> (control = on -> runtime PM disabled, see Documentation/power/runtime_pm.txt)

The document is online at [1].

For some reason the ethernet controller is not listed under
`/sys/devices`.

$ lspci | grep RTL
02:00.0 Ethernet controller: Realtek Semiconductor Co., Ltd. RTL8111/8168B PCI Express Gigabit Ethernet controller (rev 01)
$ lspci -n -s 02:00.0
02:00.0 0200: 10ec:8168 (rev 01)
$ ls /sys/devices/
breakpoint i2c-2 LNXSYSTM:00 pnp0 tracepoint
cpu i2c-3 pci0000:00 software virtual
i2c-1 i2c-4 platform system

I use `/sys/bus/pci/devices` instead.

$ more /sys/bus/pci/devices/0000:02:00.0/power/{control,runtime_enabled,runtime_status}
::::::::::::::
/sys/bus/pci/devices/0000:02:00.0/power/control
::::::::::::::
on
--More--(Next file: /sys/bus/pci/devices/0000:02:00.0/power/runtime_::::::::::::::
/sys/bus/pci/devices/0000:02:00.0/power/runtime_enabled
::::::::::::::
forbidden
--More--(Next file: /sys/bus/pci/devices/0000:02:00.0/power/runtime_::::::::::::::
/sys/bus/pci/devices/0000:02:00.0/power/runtime_status
::::::::::::::
active

> If it is enabled and the link does not come up fast enough (5 s), runtime
> PM will suspend the device. It should not matter as long as the link is
> still present because the device should (TM) soon generate a power management
> event. The latter not happening or the PME being ignored could explain
> the bug. If so, temporarily disabling runtime PM for your device after a
> failed resume instead of removing the module or the cable may be enough
> to recover the link. It's just a guess though.

So judging from the output above runtime power management is disabled
after a fresh boot and (a successful) resume and something else went
wrong.

I will report back as soon as I get a failed resume.

> Please stay with v3.2 or above in the meantime.

I will.


Thanks,

Paul


[1] http://git.kernel.org/?p=linux/kernel/git/torvalds/linux.git;a=blob;f=Documentation/power/runtime_pm.txt;h=4abe83e1045a4b38e85b05ebfeb3e8e62 841a7f6;hb=HEAD

Am Mittwoch, den 08.02.2012, 16:28 +0100 schrieb Paul Menzel:

> Am Sonntag, den 05.02.2012, 18:57 +0100 schrieb Francois Romieu:
> > Paul Menzel <pm.debian@googlemail.com> :
> > [http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=656331]
> > > I experienced this problem (only) three times until now. If I remember
> > > correctly the last time with 3.2.1. I still do not know how to reproduce
> > > this.
> >
> > (good PR, nice)
> >
> > An 'ethtool -d' and a 'mii-tool -v' of the device after a successful resume
> > and a failed one could help if it's a driver thing.
>
> The problem has not shown up again until now so I only send the output
> from the successful resume. Currently Linux version 3.2.4 is installed.

Right on time a suspend cycle later the problem turned up again.

> The following outputs are identical after startup and (a successful)
> resume.
>
> $ sudo ethtool --version
> ethtool version 3.1
> $ sudo ethtool eth0 # The option `-d` does not exist.
> Settings for eth0:
> Supported ports: [ TP MII ]
> Supported link modes: 10baseT/Half 10baseT/Full
> 100baseT/Half 100baseT/Full
> 1000baseT/Half 1000baseT/Full
> Supported pause frame use: No
> Supports auto-negotiation: Yes
> Advertised link modes: 10baseT/Half 10baseT/Full
> 100baseT/Half 100baseT/Full
> 1000baseT/Half 1000baseT/Full
> Advertised pause frame use: Symmetric Receive-only
> Advertised auto-negotiation: Yes
> Link partner advertised link modes: 10baseT/Half 10baseT/Full
> 100baseT/Half 100baseT/Full
> Link partner advertised pause frame use: Symmetric
> Link partner advertised auto-negotiation: Yes
> Speed: 100Mb/s
> Duplex: Full
> Port: MII
> PHYAD: 0
> Transceiver: internal
> Auto-negotiation: on
> Supports Wake-on: pumbg
> Wake-on: g
> Current message level: 0x00000033 (51)
> drv probe ifdown ifup
> Link detected: yes

Now from a failed resume.

$ sudo ethtool eth0
Settings for eth0:
Supported ports: [ TP MII ]
Supported link modes: 10baseT/Half 10baseT/Full
100baseT/Half 100baseT/Full
1000baseT/Half 1000baseT/Full
Supported pause frame use: No
Supports auto-negotiation: Yes
Advertised link modes: 10baseT/Half 10baseT/Full
100baseT/Half 100baseT/Full
1000baseT/Half 1000baseT/Full
Advertised pause frame use: Symmetric Receive-only
Advertised auto-negotiation: Yes
Link partner advertised link modes: 10baseT/Half 10baseT/Full
100baseT/Half 100baseT/Full
Link partner advertised pause frame use: Symmetric
Link partner advertised auto-negotiation: Yes
Speed: 100Mb/s
Duplex: Full
Port: MII
PHYAD: 0
Transceiver: internal
Auto-negotiation: on
Supports Wake-on: pumbg
Wake-on: g
Current message level: 0x00000033 (51)
drv probe ifdown ifup

I could not spot a difference.

> $ sudo mii-tool --version
> $Id: mii-tool.c,v 1.9 2006/09/27 20:59:18 ecki Exp $
> (Author: David Hinds based on Donald Becker's mii-diag)
> net-tools 1.60
> $ sudo mii-tool -v
> eth0: negotiated 100baseTx-FD flow-control, link ok
> product info: vendor 00:07:32, model 17 rev 2
> basic mode: autonegotiation enabled
> basic status: autonegotiation complete, link ok
> capabilities: 1000baseT-HD 1000baseT-FD 100baseTx-FD 100baseTx-HD 10baseT-FD 10baseT-HD
> advertising: 100baseTx-FD 100baseTx-HD 10baseT-FD 10baseT-HD flow-control
> link partner: 1000baseT-HD 1000baseT-FD 100baseTx-FD 100baseTx-HD 10baseT-FD 10baseT-HD flow-control

From a failed resume it looks like the following.

$ sudo mii-tool -v
eth0: negotiated 100baseTx-FD flow-control, link ok
product info: vendor 00:07:32, model 17 rev 2
basic mode: autonegotiation enabled
basic status: autonegotiation complete, link ok
capabilities: 1000baseT-HD 1000baseT-FD 100baseTx-FD 100baseTx-HD 10baseT-FD 10baseT-HD
advertising: 100baseTx-FD 100baseTx-HD 10baseT-FD 10baseT-HD flow-control
link partner: 1000baseT-HD 1000baseT-FD 100baseTx-FD 100baseTx-HD 10baseT-FD 10baseT-HD flow-control

This seems to be identical too.

> > You may check if runtime power management is enabled or not, especially
> > after a failed resume. See the /sys/devices/pci....:../....:..:..../power
> > directory and its control, runtime_enabled and runtime_status files
> > (control = on -> runtime PM disabled, see Documentation/power/runtime_pm.txt)
>
> The document is online at [1].
>
> For some reason the Ethernet controller is not listed under
> `/sys/devices`.
>
> $ lspci | grep RTL
> 02:00.0 Ethernet controller: Realtek Semiconductor Co., Ltd. RTL8111/8168B PCI Express Gigabit Ethernet controller (rev 01)
> $ lspci -n -s 02:00.0
> 02:00.0 0200: 10ec:8168 (rev 01)
> $ ls /sys/devices/
> breakpoint i2c-2 LNXSYSTM:00 pnp0 tracepoint
> cpu i2c-3 pci0000:00 software virtual
> i2c-1 i2c-4 platform system
>
> I use `/sys/bus/pci/devices` instead.
>
> $ more /sys/bus/pci/devices/0000:02:00.0/power/{control,runtime_enabled,runtime_status}
> ::::::::::::::
> /sys/bus/pci/devices/0000:02:00.0/power/control
> ::::::::::::::
> on
> --More--(Next file: /sys/bus/pci/devices/0000:02:00.0/power/runtime_::::::::::::::
> /sys/bus/pci/devices/0000:02:00.0/power/runtime_enabled
> ::::::::::::::
> forbidden
> --More--(Next file: /sys/bus/pci/devices/0000:02:00.0/power/runtime_::::::::::::::
> /sys/bus/pci/devices/0000:02:00.0/power/runtime_status
> ::::::::::::::
> active

From a failed resume the output is like the following.

$ more /sys/bus/pci/devices/0000:02:00.0/power/{control,runtime_enabled,runtime_status}
::::::::::::::
/sys/bus/pci/devices/0000:02:00.0/power/control
::::::::::::::
on
::::::::::::::
/sys/bus/pci/devices/0000:02:00.0/power/runtime_enabled
::::::::::::::
forbidden
::::::::::::::
/sys/bus/pci/devices/0000:02:00.0/power/runtime_status
::::::::::::::
active

This also seems identical.

> > If it is enabled and the link does not come up fast enough (5 s), runtime
> > PM will suspend the device. It should not matter as long as the link is
> > still present because the device should (TM) soon generate a power management
> > event. The latter not happening or the PME being ignored could explain
> > the bug. If so, temporarily disabling runtime PM for your device after a
> > failed resume instead of removing the module or the cable may be enough
> > to recover the link. It's just a guess though.
>
> So judging from the output above runtime power management is disabled
> after a fresh boot and (a successful) resume and something else went
> wrong.
>
> I will report back as soon as I get a failed resume.

Unfortunately I was not able to change the control parameter and always
got »The argument is invalid.« as an response.

# echo off > /sys/bus/pci/devices/0000:02:00.0/power/control
bash: echo: Schreibfehler: Das Argument ist ungültig.
# echo 1 > /sys/bus/pci/devices/0000:02:00.0/power/control
bash: echo: Schreibfehler: Das Argument ist ungültig.
# echo 0 > /sys/bus/pci/devices/0000:02:00.0/power/control
bash: echo: Schreibfehler: Das Argument ist ungültig.

Here are now some more values and outputs from a failed resume. Maybe
they are useful.

$ more /sys/bus/pci/devices/0000:02:00.0/power/runtime_*
::::::::::::::
/sys/bus/pci/devices/0000:02:00.0/power/runtime_active_kids
::::::::::::::
0
::::::::::::::
/sys/bus/pci/devices/0000:02:00.0/power/runtime_active_time
::::::::::::::
19474892
::::::::::::::
/sys/bus/pci/devices/0000:02:00.0/power/runtime_enabled
::::::::::::::
forbidden
::::::::::::::
/sys/bus/pci/devices/0000:02:00.0/power/runtime_status
::::::::::::::
active
::::::::::::::
/sys/bus/pci/devices/0000:02:00.0/power/runtime_suspended_time
::::::::::::::
0
::::::::::::::
/sys/bus/pci/devices/0000:02:00.0/power/runtime_usage
::::::::::::::
1

Now when the module was reloaded.

$ more /sys/bus/pci/devices/0000:02:00.0/power/runtime_*
::::::::::::::
/sys/bus/pci/devices/0000:02:00.0/power/runtime_active_kids
::::::::::::::
0
::::::::::::::
/sys/bus/pci/devices/0000:02:00.0/power/runtime_active_time
::::::::::::::
20478940
::::::::::::::
/sys/bus/pci/devices/0000:02:00.0/power/runtime_enabled
::::::::::::::
forbidden
::::::::::::::
/sys/bus/pci/devices/0000:02:00.0/power/runtime_status
::::::::::::::
active
::::::::::::::
/sys/bus/pci/devices/0000:02:00.0/power/runtime_suspended_time
::::::::::::::
0
::::::::::::::
/sys/bus/pci/devices/0000:02:00.0/power/runtime_usage
::::::::::::::
1

Here is the output from `dmesg`.

$ dmesg | grep 8169
[ 1.208236] r8169 Gigabit Ethernet driver 2.3LK-NAPI loaded
[ 1.208291] r8169 0000:02:00.0: PCI INT A -> GSI 19 (level, low) -> IRQ 19
[ 1.208328] r8169 0000:02:00.0: setting latency timer to 64
[ 1.208388] r8169 0000:02:00.0: irq 41 for MSI/MSI-X
[ 1.208944] r8169 0000:02:00.0: eth0: RTL8168b/8111b at 0xffffc90000324000, 00:1e:8c:aa:1d:b5, XID 18000000 IRQ 41
[ 1.208949] r8169 0000:02:00.0: eth0: jumbo features [frames: 4080 bytes, tx checksumming: ko]
[ 102.065361] r8169 0000:02:00.0: eth0: link down
[ 102.065378] r8169 0000:02:00.0: eth0: link down
[ 104.172037] r8169 0000:02:00.0: eth0: link up

I am not sure why the above is there. Maybe due to some package upgrades.

# Successful resume.

[10395.370894] r8169 0000:02:00.0: eth0: link down
[10395.761847] r8169 0000:02:00.0: PME# enabled
[10395.909944] r8169 0000:02:00.0: restoring config space at offset 0xf (was 0x100, writing 0x10a)
[10395.909960] r8169 0000:02:00.0: restoring config space at offset 0x6 (was 0x4, writing 0xfdaff004)
[10395.909967] r8169 0000:02:00.0: restoring config space at offset 0x4 (was 0x1, writing 0xdc01)
[10395.909972] r8169 0000:02:00.0: restoring config space at offset 0x3 (was 0x0, writing 0x8)
[10395.909979] r8169 0000:02:00.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100407)
[10395.910580] r8169 0000:02:00.0: PME# disabled
[10395.928147] r8169 0000:02:00.0: eth0: link down
[10397.978212] r8169 0000:02:00.0: eth0: link up

# Failed resume.

[18764.809975] r8169 0000:02:00.0: PME# enabled
[18764.957890] r8169 0000:02:00.0: restoring config space at offset 0xf (was 0x100, writing 0x10a)
[18764.957906] r8169 0000:02:00.0: restoring config space at offset 0x6 (was 0x4, writing 0xfdaff004)
[18764.957913] r8169 0000:02:00.0: restoring config space at offset 0x4 (was 0x1, writing 0xdc01)
[18764.957918] r8169 0000:02:00.0: restoring config space at offset 0x3 (was 0x0, writing 0x8)
[18764.957925] r8169 0000:02:00.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100407)
[18764.958557] r8169 0000:02:00.0: PME# disabled
[18781.998004] r8169 0000:02:00.0: eth0: link down
[18781.998024] r8169 0000:02:00.0: eth0: link down

# Reloading the module.

[19589.784094] r8169 0000:02:00.0: PCI INT A disabled
[19592.483547] r8169 Gigabit Ethernet driver 2.3LK-NAPI loaded
[19592.483618] r8169 0000:02:00.0: PCI INT A -> GSI 19 (level, low) -> IRQ 19
[19592.483689] r8169 0000:02:00.0: setting latency timer to 64
[19592.483783] r8169 0000:02:00.0: irq 41 for MSI/MSI-X
[19592.485394] r8169 0000:02:00.0: eth0: RTL8168b/8111b at 0xffffc90000324000, 00:1e:8c:aa:1d:b5, XID 18000000 IRQ 41
[19592.485404] r8169 0000:02:00.0: eth0: jumbo features [frames: 4080 bytes, tx checksumming: ko]
[19592.913672] r8169 0000:02:00.0: eth0: link down
[19594.947829] r8169 0000:02:00.0: eth0: link up


> > Please stay with v3.2 or above in the meantime.
>
> I will.


Thanks,

Paul


> [1] http://git.kernel.org/?p=linux/kernel/git/torvalds/linux.git;a=blob;f=Documentation/power/runtime_pm.txt;h=4abe83e1045a4b38e85b05ebfeb3e8e62 841a7f6;hb=HEAD

Paul Menzel <pm.debian@googlemail.com> :
[forget runtime PM]
> [18764.958557] r8169 0000:02:00.0: PME# disabled
> [18781.998004] r8169 0000:02:00.0: eth0: link down
^^
> [18781.998024] r8169 0000:02:00.0: eth0: link down
^^
Two link events within 20 us. /me wonders...

The datasheet states "[the PHYStatus] register is updated continuously at
maximum periods of 300us." but it is far from clear that the coherency
with the interrupt status register can be taken for granted. Hayes ?

Paul, can you try the hack below ?

diff --git a/drivers/net/ethernet/realtek/r8169.c b/drivers/net/ethernet/realtek/r8169.c
index 7a0c800..6daca05 100644
--- a/drivers/net/ethernet/realtek/r8169.c
+++ b/drivers/net/ethernet/realtek/r8169.c
@@ -1278,6 +1278,7 @@ static void __rtl8169_check_link_status(struct net_device *dev,
{
unsigned long flags;

+ udelay(500);
spin_lock_irqsave(&tp->lock, flags);
if (tp->link_ok(ioaddr)) {
rtl_link_chg_patch(tp);



--
To UNSUBSCRIBE, email to debian-kernel-REQUEST@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listmaster@lists.debian.org
Archive: 20120208221644.GA25538@electric-eye.fr.zoreil.com">http://lists.debian.org/20120208221644.GA25538@electric-eye.fr.zoreil.com

Am Mittwoch, den 08.02.2012, 23:16 +0100 schrieb Francois Romieu:
> Paul Menzel <pm.debian@googlemail.com> :

[…]

> > [18764.958557] r8169 0000:02:00.0: PME# disabled
> > [18781.998004] r8169 0000:02:00.0: eth0: link down
> ^^
> > [18781.998024] r8169 0000:02:00.0: eth0: link down
> ^^
> Two link events within 20 us. /me wonders...

[20195.408746] r8169 0000:02:00.0: PME# enabled
[20195.466159] r8169 0000:02:00.0: restoring config space at offset 0xf (was 0x100, writing 0x10a)
[20195.466175] r8169 0000:02:00.0: restoring config space at offset 0x6 (was 0x4, writing 0xfdaff004)
[20195.466182] r8169 0000:02:00.0: restoring config space at offset 0x4 (was 0x1, writing 0xdc01)
[20195.466187] r8169 0000:02:00.0: restoring config space at offset 0x3 (was 0x0, writing 0x8)
[20195.466194] r8169 0000:02:00.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100407)
[20195.466826] r8169 0000:02:00.0: PME# disabled
[20211.376483] r8169 0000:02:00.0: eth0: link down
[20211.376507] r8169 0000:02:00.0: eth0: link down

Only ten 24 us difference. But during this resume process the network
came back up fine. Also in my prior pasted output this is also shown at
the beginning but the network worked fine.

[20213.000840] r8169 0000:02:00.0: eth0: link up
[32598.618289] r8169 0000:02:00.0: eth0: link down

This event during resume sometimes shows up and sometimes it does not. I
could not find a correlation between successful and failed resumes.

[32599.249802] r8169 0000:02:00.0: PME# enabled
[32599.397941] r8169 0000:02:00.0: restoring config space at offset 0xf (was 0x100, writing 0x10a)
[32599.397956] r8169 0000:02:00.0: restoring config space at offset 0x6 (was 0x4, writing 0xfdaff004)
[32599.397963] r8169 0000:02:00.0: restoring config space at offset 0x4 (was 0x1, writing 0xdc01)
[32599.397968] r8169 0000:02:00.0: restoring config space at offset 0x3 (was 0x0, writing 0x8)
[32599.397975] r8169 0000:02:00.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100407)
[32599.398766] r8169 0000:02:00.0: PME# disabled
[32599.416148] r8169 0000:02:00.0: eth0: link down

Here it did not work and the link did not come back up. There is over half a second time bet

[32673.504101] r8169 0000:02:00.0: PCI INT A disabled

The module is removed and loaded below.

[32676.218019] r8169 Gigabit Ethernet driver 2.3LK-NAPI loaded
[32676.218078] r8169 0000:02:00.0: PCI INT A -> GSI 19 (level, low) -> IRQ 19
[32676.218152] r8169 0000:02:00.0: setting latency timer to 64
[32676.218246] r8169 0000:02:00.0: irq 41 for MSI/MSI-X
[32676.219792] r8169 0000:02:00.0: eth0: RTL8168b/8111b at 0xffffc90000368000, 00:1e:8c:aa:1d:b5, XID 18000000 IRQ 41
[32676.219803] r8169 0000:02:00.0: eth0: jumbo features [frames: 4080 bytes, tx checksumming: ko]
[32676.563203] r8169 0000:02:00.0: eth0: link down
[32678.356237] r8169 0000:02:00.0: eth0: link up

> The datasheet states "[the PHYStatus] register is updated continuously at
> maximum periods of 300us." but it is far from clear that the coherency
> with the interrupt status register can be taken for granted. Hayes ?
>
> Paul, can you try the hack below ?
>
> diff --git a/drivers/net/ethernet/realtek/r8169.c b/drivers/net/ethernet/realtek/r8169.c
> index 7a0c800..6daca05 100644
> --- a/drivers/net/ethernet/realtek/r8169.c
> +++ b/drivers/net/ethernet/realtek/r8169.c
> @@ -1278,6 +1278,7 @@ static void __rtl8169_check_link_status(struct net_device *dev,
> {
> unsigned long flags;
>
> + udelay(500);
> spin_lock_irqsave(&tp->lock, flags);
> if (tp->link_ok(ioaddr)) {
> rtl_link_chg_patch(tp);

I will try this hack next week. Thank you!

Could it be that there is something wrong with the locking though or
parallel execution? Sometimes

[32598.618289] r8169 0000:02:00.0: eth0: link down

is shown before

[32599.249802] r8169 0000:02:00.0: PME# enabled

and sometimes it is not or only afterward.


Thanks,

Paul