Re: Mass udp flow reboot linux with RealTek RTL-8169 Gigabit

From: Seblu
Date: Sat Mar 05 2011 - 19:29:45 EST

On Fri, Feb 18, 2011 at 10:30 AM, Francois Romieu <romieu@xxxxxxxxxxxxx> wrote:
> Seblu <seblu@xxxxxxxxx> :
> [...]
>> 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 ]---

>> 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

Attachment: dmesg.2.6.38-rc7-seblu-patched.xz
Description: application/xz

Attachment: config-2.6.38-rc7-seblu-patched.xz
Description: application/xz