Le dimanche 13 février 2011 à 02:35 +0100, Seblu a écrit :
Hi,
CC netdev
Some days ago, one of my computer poweroff without any warning during
a long rsync. Every time i run this long rsync, my computer power off
after a random time.
Firstly i suspected a heat stroke. But it resisted all my heat tests
(cpuburn,ffmpeg,etc).
Secondly i suposed a power issue. But after some tests, it does not
seem to be kind of problem.
Thirdly, i trying to load disk by a lot of read. But system is stable.
Which is not practical, is that there is no message or trace in logs
file. And why power off? BIOS is configured to restart after a
powerloss.
So, maybe a network issue? From one another 1Gbit/s wired linux
computer i tryed an udp iperf at full speed (got ~950mbps) and after
some time, host reboot. o0
I tryed again, and host reboot again. I tryed with "ping -s 65000 -f"
and my host reboot again. I've tryed this with a 2.6.32 (debian
squeeze) and a 2.6.37 (debian experimental) kernel, in both case
host reboot.
This doesn't explain why my host power off when rsync, but it seems to
have a big issue with kernel driver r8169.
After starting my flood ping or udp iperf, dmesg show a lot of line:
[ 254.896055] r8169 0000:04:00.0: eth0: link up
[ 254.919976] r8169 0000:04:00.0: eth0: link up
[ 254.943916] r8169 0000:04:00.0: eth0: link up
[ 254.983784] r8169 0000:04:00.0: eth0: link up
[ 255.007710] r8169 0000:04:00.0: eth0: link up
[ 255.031657] r8169 0000:04:00.0: eth0: link up
[ 255.103444] r8169 0000:04:00.0: eth0: link up
Reboot is curious because it doesnt look like a kernel panic and print
there is no kernel trace.
My OS is a debian squeeze amd64. My hardware is a intel core i3 +
gigabyte H55N-UBS3 with 4G DDR3.
Do you need more trace / test? Do you think power off and reboot is linked?
r8169 driver is known to trigger a reset in case of RX overflow (but a
NIC reset should not power off the machine)
Some attempts were done to avoid a reset on some chipsets.
You could try latest linux-2.6 tree. This includes commits
f60ac8e7ab7cbb413a0131d5665b053f9f386526 (r8169: prevent RxFIFO induced
loops in the irq handler.)
1519e57fe81c14bb8fa4855579f19264d1ef63b4 (r8169: RxFIFO overflow
oddities with 8168 chipsets.)
b5ba6d12bdac21bc0620a5089e0f24e362645efd (r8169: use RxFIFO overflow
workaround for 8168c chipset.)
On Sun, Feb 13, 2011 at 2:56 PM, Francois Romieu [off-list ref] wrote:
Eric Dumazet [off-list ref] :
If it still does not perform better, please include the XID line of
the r8169 driver from dmesg.
I've tryed on archlinux i686 distro with 2.6.37 and host reboot like
under debian.
After this, i tryed wiith a 2.6.38-rc4 (amd64), which include your
recent patchs.
# dmesg|grep -i xid
r8169 0000:04:00.0: eth0: RTL8168b/8111b at 0xffffc90005260000,
1c:6f:65:56:d9:17, XID 0c200000 IRQ 47
NIC seems to be reset frequently but host stop rebooting. \o//
r8169 0000:04:00.0: eth0: link up
net_ratelimit: 317 callbacks suppressed
r8169 0000:04:00.0: eth0: link up
...
net_ratelimit: 312 callbacks suppressed
r8169 0000:04:00.0: eth0: link up
i noticed a strange behaviour:
I run an iperf from computer A (gigabit plugged).
I run an ping -f from computer A.
A lot of pintk like previous one is printed on console (dmesg -n 8)
if i run an iperf from a computer B (fast eth plugged)
pings is not answered (computer A) and printk message disapear (on target)
if i run this 2nd iperf from computer A, disable iperf from computer
B, printk and ping answers are back.
i attached dmesg output.
Regards,
--
Sébastien Luttringer
www.seblu.net
On Fri, Feb 18, 2011 at 10:30 AM, Francois Romieu [off-list ref] wrote:
Seblu [off-list ref] :
[...]
quoted
I've applyed your patch on 2.6.38-rc5. Host have rebooted 2mn after udp start.
After this reboot, host is still on after 2 hour under a 1Gbit/s udp flow.
Thanks for testing.
Thanks for debugging! Sorry for the late reply.
I catched the following trace during my previous torture session.
Maybe it can help.
[ 1448.189961] ------------[ cut here ]------------
[ 1448.189968] WARNING: at net/sched/sch_generic.c:256
dev_watchdog+0x104/0x1ad()
[ 1448.189970] Hardware name: H55N-USB3
[ 1448.189971] NETDEV WATCHDOG: eth0 (r8169): transmit queue 0 timed out
[ 1448.189972] Modules linked in: ext2 it87 hwmon_vid ds1621 i915
drm_kms_helper drm i2c_algo_bit video dm_crypt raid456
async_raid6_recov async_pq raid6_pq async_xor xor async_memcpy
async_tx md_mod option usb_wwan r8169 snd_pcm snd_timer snd soundcore
usbserial uhci_hcd xhci_hcd ehci_hcd usbcore tpm_tis evdev i2c_i801
tpm processor snd_page_alloc mii sata_mv pcspkr serio_raw i2c_core
tpm_bios button thermal_sys nls_base ext4 mbcache jbd2 crc16 dm_mod
btrfs zlib_deflate crc32c libcrc32c sd_mod crc_t10dif ahci libahci
libata scsi_mod
[ 1448.190006] Pid: 0, comm: kworker/0:1 Not tainted 2.6.38-rc5-seblu #2
[ 1448.190007] Call Trace:
[ 1448.190009] <IRQ> [<ffffffff8103a198>] ? warn_slowpath_common+0x78/0x8c
[ 1448.190016] [<ffffffff8103a24b>] ? warn_slowpath_fmt+0x45/0x4a
[ 1448.190018] [<ffffffff8126a718>] ? netif_tx_lock+0x43/0x74
[ 1448.190019] [<ffffffff8126a84d>] ? dev_watchdog+0x104/0x1ad
[ 1448.190023] [<ffffffff8104e80f>] ? __queue_work+0x30c/0x334
[ 1448.190026] [<ffffffff81045ff3>] ? run_timer_softirq+0x1b8/0x27b
[ 1448.190028] [<ffffffff8126a749>] ? dev_watchdog+0x0/0x1ad
[ 1448.190031] [<ffffffff8105a726>] ? ktime_get+0x5f/0xb8
[ 1448.190034] [<ffffffff8103fa09>] ? __do_softirq+0xbd/0x194
[ 1448.190037] [<ffffffff810037cc>] ? call_softirq+0x1c/0x28
[ 1448.190040] [<ffffffff81004bb5>] ? do_softirq+0x31/0x63
[ 1448.190042] [<ffffffff8103f8b1>] ? irq_exit+0x36/0x7b
[ 1448.190045] [<ffffffff8101843c>] ? smp_apic_timer_interrupt+0x87/0x94
[ 1448.190047] [<ffffffff81003293>] ? apic_timer_interrupt+0x13/0x20
[ 1448.190048] <EOI> [<ffffffff81056250>] ? hrtimer_get_next_event+0x8a/0xa2
[ 1448.190056] [<ffffffffa0128d11>] ? acpi_idle_enter_c1+0x7b/0x95 [processor]
[ 1448.190059] [<ffffffffa0128cf1>] ? acpi_idle_enter_c1+0x5b/0x95 [processor]
[ 1448.190063] [<ffffffff8123c097>] ? cpuidle_idle_call+0x119/0x1c6
[ 1448.190065] [<ffffffff81001c9c>] ? cpu_idle+0xa5/0xdb
[ 1448.190068] [<ffffffff812ffd4a>] ? start_secondary+0x1ad/0x1b3
[ 1448.190070] ---[ end trace dd5a8baf361d8b47 ]---
quoted
I attached a dmesg output before reboot. Do you need anything else?
ok. next informations is about test with patch
r8169-TX-stop-queue-race-fix and r8169-debuginator on 2.6.38-rc7.
Mostly :
1. .config
see attachment
2. the size of the udp packets and the mtu
eth0 mtu is 1500
iperf output:
Client connecting to bitume, UDP port 5001
Sending 1470 byte datagrams
UDP buffer size: 122 KByte (default)
and icmp echo have size of 65500.
As an option :
3. a few seconds of 'vmstat 1' from the host under test
procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu----
r b swpd free buff cache si so bi bo in cs us sy id wa
0 0 0 3720532 11292 43292 0 0 15 2 2356 4160 0 1 98 1
0 0 0 3720524 11300 43316 0 0 0 20 21459 41637 0 2 97 2
1 0 0 3720420 11300 43316 0 0 0 0 20565 39521 1 1 98 0
0 0 0 3720588 11300 43316 0 0 0 0 21451 41569 0 1 99 0
0 0 0 3720492 11300 43316 0 0 0 0 21492 41441 0 1 98 0
0 0 0 3720564 11300 43316 0 0 0 0 21475 41435 0 2 98 0
1 0 0 3720500 11308 43320 0 0 0 16 21485 41675 1 1 97 1
1 0 0 3720556 11308 43320 0 0 0 0 17940 33773 0 1 99 0
0 0 0 3720588 11308 43320 0 0 0 0 9472 16384 0 1 100 0
0 0 0 3720660 11308 43320 0 0 0 0 8769 15217 1 1 99 0
0 0 0 3720484 11308 43320 0 0 0 0 10137 17766 0 1 99 0
2 0 0 3720524 11316 43324 0 0 0 16 9760 16907 0 1 98 2
0 0 0 3720492 11316 43324 0 0 0 0 9956 17138 0 1 99 0
0 0 0 3720492 11316 43324 0 0 0 0 9927 17220 0 0 99 0
1 0 0 3720524 11316 43324 0 0 0 0 10543 18502
0 0 100 0
1 0 0 3720596 11316 43324 0 0 0 0 9600 16409 0 1 99 0
0 0 0 3720564 11324 43324 0 0 0 60 9953 17339 0 1 98 1
0 0 0 3720460 11324 43324 0 0 0 0 9503 16583 0 0 99 0
0 0 0 3720684 11324 43324 0 0 0 0 9106 15637 0 1 99 0
0 0 0 3720460 11324 43324 0 0 0 0 9800 17019 0 1 99 0
0 0 0 3720492 11324 43324 0 0 0 0 9522 16559 0 0 99 0
0 0 0 3720428 11332 43328 0 0 0 28 9789 17106 0 1 97 2
0 0 0 3720460 11332 43328 0 0 0 0 10157 17717 0 1 99 0
0 0 0 3720564 11332 43328 0 0 0 0 9882 16940 0 0 100 0
0 0 0 3720492 11332 43328 0 0 0 0 9360 15991 0 0 100 0
0 0 0 3720492 11332 43328 0 0 0 0 10096 17436 0 0 99 0
0 0 0 3720556 11340 43328 0 0 0 28 9224 16028 0 1 97 2
0 0 0 3720500 11340 43328 0 0 0 0 9154 15942 0 1 99 0
1 0 0 3720524 11340 43328 0 0 0 0 10309 17781 0 1 99 0
4. an 'ethtool -s eth0' from the host under test
# ethtool -S eth0
NIC statistics:
tx_packets: 2598554
rx_packets: 35146015
tx_errors: 0
rx_errors: 0
rx_missed: 27571
align_errors: 0
tx_single_collisions: 0
tx_multi_collisions: 0
unicast: 35145983
broadcast: 24
multicast: 8
tx_aborted: 0
tx_underrun: 0
5. /proc/interrupts from the host under test
CPU0 CPU1 CPU2 CPU3
0: 40 1 0 2 IO-APIC-edge timer
1: 1 0 0 1 IO-APIC-edge i8042
8: 0 0 1 0 IO-APIC-edge rtc0
9: 0 0 0 0 IO-APIC-fasteoi acpi
16: 135 135 130 124 IO-APIC-fasteoi
sata_mv, uhci_hcd:usb4
18: 0 0 0 0 IO-APIC-fasteoi
ehci_hcd:usb1, uhci_hcd:usb6, uhci_hcd:usb9
19: 0 0 0 0 IO-APIC-fasteoi
uhci_hcd:usb8
21: 0 0 0 0 IO-APIC-fasteoi
uhci_hcd:usb5
23: 0 0 0 0 IO-APIC-fasteoi
ehci_hcd:usb3, uhci_hcd:usb7
41: 1196 1164 1206 1197 PCI-MSI-edge ahci
42: 0 0 0 1 PCI-MSI-edge xhci_hcd
43: 0 0 0 0 PCI-MSI-edge xhci_hcd
44: 0 0 0 0 PCI-MSI-edge xhci_hcd
45: 0 0 0 0 PCI-MSI-edge xhci_hcd
46: 0 0 0 0 PCI-MSI-edge xhci_hcd
47: 2517359 2517695 2517327 2517689 PCI-MSI-edge eth0
48: 0 0 0 0 PCI-MSI-edge i915
NMI: 64 64 63 61 Non-maskable interrupts
LOC: 189057 173286 183692 172647 Local timer interrupts
SPU: 0 0 0 0 Spurious interrupts
PMI: 64 64 63 61 Performance
monitoring interrupts
IWI: 0 0 0 0 IRQ work interrupts
RES: 75 82 102 65 Rescheduling interrupts
CAL: 93 129 107 125 Function call interrupts
TLB: 105 111 238 322 TLB shootdowns
TRM: 0 0 0 0 Thermal event interrupts
THR: 0 0 0 0 Threshold APIC interrupts
MCE: 0 0 0 0 Machine check exceptions
MCP: 5 5 5 5 Machine check polls
ERR: 3
MIS: 0
6. lspci -tv
-[0000:00]-+-00.0 Intel Corporation Core Processor DRAM Controller
+-01.0-[01]----00.0 Adaptec Serial ATA II RAID 1430SA
+-02.0 Intel Corporation Core Processor Integrated
Graphics Controller
+-16.0 Intel Corporation 5 Series/3400 Series Chipset HECI
Controller
+-1a.0 Intel Corporation 5 Series/3400 Series Chipset USB
Universal Host Controller
+-1a.1 Intel Corporation 5 Series/3400 Series Chipset USB
Universal Host Controller
+-1a.2 Intel Corporation 5 Series/3400 Series Chipset USB
Universal Host Controller
+-1a.7 Intel Corporation 5 Series/3400 Series Chipset USB2
Enhanced Host Controller
+-1c.0-[02]--
+-1c.3-[03]----00.0 NEC Corporation uPD720200 USB 3.0 Host
Controller
+-1c.5-[04]----00.0 Realtek Semiconductor Co., Ltd.
RTL8111/8168B PCI Express Gigabit Ethernet controller
+-1d.0 Intel Corporation 5 Series/3400 Series Chipset USB
Universal Host Controller
+-1d.1 Intel Corporation 5 Series/3400 Series Chipset USB
Universal Host Controller
+-1d.2 Intel Corporation 5 Series/3400 Series Chipset USB
Universal Host Controller
+-1d.7 Intel Corporation 5 Series/3400 Series Chipset USB2
Enhanced Host Controller
+-1e.0-[05]--
+-1f.0 Intel Corporation 5 Series Chipset LPC Interface Controller
+-1f.2 Intel Corporation 5 Series/3400 Series Chipset 6
port SATA AHCI Controller
\-1f.3 Intel Corporation 5 Series/3400 Series Chipset
SMBus Controller
Can you apply the two attached patches on top of the previous ones and
give it a try ? The debug should not be too verbose if things are stationary
enough.
2.6.38-rc7 with your 2 previous patch change the game. No reboot. No
strange message in dmesg.
But somes sended packet are lost from some host. Example:
thunder ~ 1 # ping bitume
PING bitume.spn (192.168.242.4) 56(84) bytes of data.
64 bytes from bitume.spn (192.168.242.4): icmp_req=9 ttl=64 time=1005 ms
64 bytes from bitume.spn (192.168.242.4): icmp_req=10 ttl=64 time=0.538 ms
64 bytes from bitume.spn (192.168.242.4): icmp_req=12 ttl=64 time=0.817 ms
64 bytes from bitume.spn (192.168.242.4): icmp_req=15 ttl=64 time=0.639 ms
64 bytes from bitume.spn (192.168.242.4): icmp_req=20 ttl=64 time=5.32 ms
64 bytes from bitume.spn (192.168.242.4): icmp_req=22 ttl=64 time=0.866 ms
64 bytes from bitume.spn (192.168.242.4): icmp_req=26 ttl=64 time=0.607 ms
bitume ~ 0 # tcpdump -lni eth0 icmp
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on eth0, link-type EN10MB (Ethernet), capture size 65535 bytes
00:23:45.713828 IP 192.168.242.5 > 192.168.242.4: ICMP echo request,
id 19486, seq 9, length 64
00:23:46.718479 IP 192.168.242.4 > 192.168.242.5: ICMP echo reply, id
19486, seq 9, length 64
00:23:46.718482 IP 192.168.242.4 > 192.168.242.5: ICMP ip reassembly
time exceeded, length 556
00:23:46.720291 IP 192.168.242.5 > 192.168.242.4: ICMP echo request,
id 19486, seq 10, length 64
00:23:46.720297 IP 192.168.242.4 > 192.168.242.5: ICMP echo reply, id
19486, seq 10, length 64
00:23:48.141013 IP 192.168.242.4 > 192.168.242.5: ICMP ip reassembly
time exceeded, length 556
00:23:48.722329 IP 192.168.242.5 > 192.168.242.4: ICMP echo request,
id 19486, seq 12, length 64
00:23:48.722335 IP 192.168.242.4 > 192.168.242.5: ICMP echo reply, id
19486, seq 12, length 64
00:23:51.741686 IP 192.168.242.5 > 192.168.242.4: ICMP echo request,
id 19486, seq 15, length 64
00:23:51.741692 IP 192.168.242.4 > 192.168.242.5: ICMP echo reply, id
19486, seq 15, length 64
00:23:56.778367 IP 192.168.242.5 > 192.168.242.4: ICMP echo request,
id 19486, seq 20, length 64
00:23:56.778373 IP 192.168.242.4 > 192.168.242.5: ICMP echo reply, id
19486, seq 20, length 64
00:23:57.988239 IP 192.168.242.2 > 192.168.242.4: ICMP ip reassembly
time exceeded, length 556
00:23:57.988243 IP 192.168.242.2 > 192.168.242.4: ICMP ip reassembly
time exceeded, length 556
00:23:57.988327 IP 192.168.242.2 > 192.168.242.4: ICMP ip reassembly
time exceeded, length 556
00:23:58.775425 IP 192.168.242.5 > 192.168.242.4: ICMP echo request,
id 19486, seq 22, length 64
00:23:58.775431 IP 192.168.242.4 > 192.168.242.5: ICMP echo reply, id
19486, seq 22, length 64
^C
17 packets captured
82 packets received by filter
0 packets dropped by kernel
This is maybe normal under stress, card discard packet after all.
Do you have a serial cable and a second computer at hand by chance (don't
go for netconsole with the r8169 driver) ?
I've a serial cable and a second computer, but my first computer
doesn't have a com port. Is it then possible?
Do you need more test?
--
Sébastien Luttringer
www.seblu.net
Seblu [off-list ref] :
[...]
I catched the following trace during my previous torture session.
Maybe it can help.
It's the usual r8169 TX timeout watchdog.
[...]
quoted
Can you apply the two attached patches on top of the previous ones and
give it a try ? The debug should not be too verbose if things are stationary
enough.
2.6.38-rc7 with your 2 previous patch change the game. No reboot. No
strange message in dmesg.
?
"strange message" as :
[ ] netdev watchdog messages
[ ] 0001 0001 0001 0001 (or similar) message
[ ] net_ratelimit message
But some sent packets are lost from some host. Example:
[...]
This is maybe normal under stress, card discard packet after all.
It seems so. 0.08% packet loss. 10 ~ 20kpps (right ?). Sample at 0.1 Hz (ping).
[...]
I've a serial cable and a second computer, but my first computer
doesn't have a com port. Is it then possible?
Hardly. Forget it for now.
Do you need more test?
1. 2.6.38-rc7 without the patches
2. 2.6.38-rc7 with the r8169.c driver of 2.6.38-rc5, without the patches
3. current setup + pktgen. Lower the packet size as long as it increases
the sender's pps.
I do not understand why the bug would be gone if it was in the r8169
proper.
--
Ueimor