New: Seg Fault Instead of Swapping

Bugme-new Andrew Morton 3 participants 11 messages May 21, 2008 – Jun 4, 2008 7 messages not in the archive

Subsystems (3)

Networking Network drivers TCP

lore

Share & tools

lore

A message that is not in the archive (sent off-list or not yet received): [email protected]/

Andrew Morton

author

2008-05-21 17:57 UTC #1 lore raw

(switched to email. Please respond via emailed reply-to-all, not via the bugzilla web interface).

Quoted 3 lines · On Wed, 21 May 2008 02:45:59 -0700 (PDT) [email protected] wrote:

http://bugzilla.kernel.org/show_bug.cgi?id=10767
Summary: Seg Fault Instead of Swapping

Strange description?

Quoted 14 lines

           Product: Networking
           Version: 2.5
     KernelVersion: 2.6.25.4
          Platform: All
        OS/Version: Linux
              Tree: Mainline
            Status: NEW
          Severity: normal
          Priority: P1
         Component: IPV4
        AssignedTo: [email protected]
        ReportedBy: [email protected]

Quoted 3 lines

May 20 13:11:00 ishtar kernel: ------------[ cut here ]------------
May 20 13:11:00 ishtar kernel: WARNING: at net/ipv4/tcp_input.c:2539

tcp_ack+0xd2b/0x191f()

In 2.6.25 this is

	if (WARN_ON(!tp->sacked_out && tp->fackets_out))
		tp->fackets_out = 0;

Quoted 46 lines

May 20 13:11:00 ishtar kernel: Modules linked in: fuse dm_mirror dm_multipath

dm_mod cfi_cmdset_0002 cfi_util jedec_probe button cfi_probe gen_probe k8temp ck804xrom hwmon mtd usb_storage chipreg serio_raw map_funcs i2c_nforce2 pcspkr i2c_core sg pata_amd cciss ata_generic pata_acpi sata_nv libata sd_mod scsi_mod raid456 async_xor async_memcpy async_tx xor raid1 uhci_hcd ohci_hcd ssb ehci_hcd [last unloaded: scsi_wait_scan]

May 20 13:11:00 ishtar kernel: Pid: 0, comm: swapper Not tainted 2.6.25.4 #1
May 20 13:11:00 ishtar kernel:
May 20 13:11:00 ishtar kernel: Call Trace:
May 20 13:11:00 ishtar kernel:  <IRQ>  [<ffffffff81034481>]
warn_on_slowpath+0x51/0x63
May 20 13:11:00 ishtar kernel:  [<ffffffff81023577>] kernel_map_pages+0xe8/0xed
May 20 13:11:00 ishtar kernel:  [<ffffffff8103ca36>] lock_timer_base+0x26/0x4c
May 20 13:11:00 ishtar kernel:  [<ffffffff812baa38>] tcp_snd_test+0x17/0xdf
May 20 13:11:00 ishtar kernel:  [<ffffffff812bab4d>] tcp_may_send_now+0x4d/0x5a
May 20 13:11:00 ishtar kernel:  [<ffffffff812b68ce>] tcp_ack+0xd2b/0x191f
May 20 13:11:00 ishtar kernel:  [<ffffffff812b9dbc>]
tcp_rcv_established+0xe2/0x8ce
May 20 13:11:00 ishtar kernel:  [<ffffffff812bffba>] tcp_v4_do_rcv+0x2c2/0x48b
May 20 13:11:00 ishtar kernel:  [<ffffffff8129a07a>] __qdisc_run+0xf6/0x1c8
May 20 13:11:00 ishtar kernel:  [<ffffffff812ae376>]
__inet_lookup_established+0xdf/0x17b
May 20 13:11:00 ishtar kernel:  [<ffffffff812c1d10>] tcp_v4_rcv+0x6a3/0x700
May 20 13:11:00 ishtar kernel:  [<ffffffff812a7558>]
ip_local_deliver+0xd4/0x18e
May 20 13:11:00 ishtar kernel:  [<ffffffff812a7b0d>] ip_rcv+0x4fb/0x53a
May 20 13:11:00 ishtar kernel:  [<ffffffff8128a2b7>]
netif_receive_skb+0x351/0x372
May 20 13:11:00 ishtar kernel:  [<ffffffff8124150d>] tg3_poll+0x588/0x7df
May 20 13:11:00 ishtar kernel:  [<ffffffff8128c2ce>] net_rx_action+0xb6/0x1bf
May 20 13:11:00 ishtar kernel:  [<ffffffff8103919b>] __do_softirq+0x65/0xce
May 20 13:11:00 ishtar kernel:  [<ffffffff8100ce9c>] call_softirq+0x1c/0x28
May 20 13:11:00 ishtar kernel:  [<ffffffff8100e544>] do_softirq+0x2c/0x68
May 20 13:11:00 ishtar kernel:  [<ffffffff810390f2>] irq_exit+0x3f/0x83
May 20 13:11:00 ishtar kernel:  [<ffffffff8100e813>] do_IRQ+0x13e/0x15f
May 20 13:11:00 ishtar kernel:  [<ffffffff8100c221>] ret_from_intr+0x0/0xa
May 20 13:11:00 ishtar kernel:  <EOI>  [<ffffffff8100adc8>]
default_idle+0x0/0x55
May 20 13:11:00 ishtar kernel:  [<ffffffff8101c138>] lapic_next_event+0x0/0xa
May 20 13:11:00 ishtar kernel:  [<ffffffff8100adc8>] default_idle+0x0/0x55
May 20 13:11:00 ishtar kernel:  [<ffffffff8100adf9>] default_idle+0x31/0x55
May 20 13:11:00 ishtar kernel:  [<ffffffff8100adf4>] default_idle+0x2c/0x55
May 20 13:11:00 ishtar kernel:  [<ffffffff8100adc8>] default_idle+0x0/0x55
May 20 13:11:00 ishtar kernel:  [<ffffffff8100ae94>] cpu_idle+0x77/0x9a
May 20 13:11:00 ishtar kernel:
May 20 13:11:00 ishtar kernel: ---[ end trace f970ab335f443aca ]---

A message that is not in the archive (sent off-list or not yet received): [email protected]

Andrew Morton

author

2008-05-21 18:53 UTC #3 lore raw

Quoted 1 line · On Wed, 21 May 2008 11:40:43 -0700 "Brian Vowell" <[email protected]>…

Please forgive my lack of technical skills-- I am not a developer.

Thank you for reporting this kernel bug!

Quoted 50 lines

The bug report referenced below recently occurred on a pretty busy file server of mine running Fedora 8 with a custom 2.6.25.4 kernel. The attached hardware RAID controller presents 12 LUNs, which were striped using the Linux mdadm tools, and then the Linux LVM was used to create a single logical volume. The filesystem used is XFS.

Since upgrading from 2.6.25.3 to 2.6.25.4, my log has shown a large number of errors that I don't possess the skills to diagnose which component is actually causing the errors. I can verify however, that the hardware is good. I have run memtest86 and the vendor's diagnostic tools and verified that everything is running well.

The errors in /var/log/messages look like this:

May 19 06:30:30 ishtar kernel: Call Trace:
May 19 06:30:30 ishtar kernel:  <IRQ>  [<ffffffff81075d35>]
__alloc_pages+0x33f/0x35a
May 19 06:30:30 ishtar kernel:  [<ffffffff8100e813>] do_IRQ+0x13e/0x15f
May 19 06:30:30 ishtar kernel:  [<ffffffff810934a4>] new_slab+0x3f/0x242
May 19 06:30:30 ishtar kernel:  [<ffffffff81093bba>]
__slab_alloc+0x212/0x43b
May 19 06:30:30 ishtar kernel:  [<ffffffff8128654c>]
__netdev_alloc_skb+0x29/0x43
May 19 06:30:30 ishtar kernel:  [<ffffffff8128654c>]
__netdev_alloc_skb+0x29/0x43
May 19 06:30:30 ishtar kernel:  [<ffffffff81094bd6>]
__kmalloc_node_track_caller+0x75/0xab
May 19 06:30:30 ishtar kernel:  [<ffffffff8128584a>] __alloc_skb+0x6a/0x133
May 19 06:30:30 ishtar kernel:  [<ffffffff8128654c>]
__netdev_alloc_skb+0x29/0x43
May 19 06:30:30 ishtar kernel:  [<ffffffff8123a405>]
tg3_alloc_rx_skb+0xc4/0x153
May 19 06:30:30 ishtar kernel:  [<ffffffff81241343>] tg3_poll+0x3be/0x7df
May 19 06:30:30 ishtar kernel:  [<ffffffff8128c2ce>]
net_rx_action+0xb6/0x1bf
May 19 06:30:30 ishtar kernel:  [<ffffffff8103919b>] __do_softirq+0x65/0xce
May 19 06:30:30 ishtar kernel:  [<ffffffff8100ce9c>] call_softirq+0x1c/0x28
May 19 06:30:30 ishtar kernel:  [<ffffffff8100e544>] do_softirq+0x2c/0x68
May 19 06:30:30 ishtar kernel:  [<ffffffff810390f2>] irq_exit+0x3f/0x83
May 19 06:30:30 ishtar kernel:  [<ffffffff8100e813>] do_IRQ+0x13e/0x15f
May 19 06:30:30 ishtar kernel:  [<ffffffff8100c221>] ret_from_intr+0x0/0xa
May 19 06:30:30 ishtar kernel:  <EOI>  [<ffffffff8100adc8>]
default_idle+0x0/0x55
May 19 06:30:30 ishtar kernel:  [<ffffffff8101c138>]
lapic_next_event+0x0/0xa
May 19 06:30:30 ishtar kernel:  [<ffffffff8100adc8>] default_idle+0x0/0x55
May 19 06:30:30 ishtar kernel:  [<ffffffff8100adf9>] default_idle+0x31/0x55
May 19 06:30:30 ishtar kernel:  [<ffffffff8100adf4>] default_idle+0x2c/0x55
May 19 06:30:30 ishtar kernel:  [<ffffffff8100adc8>] default_idle+0x0/0x55
May 19 06:30:30 ishtar kernel:  [<ffffffff8100ae94>] cpu_idle+0x77/0x9a

Quoted 7 lines

The hardware is an HP Proliant DL145G2, Dual Core Opteron 275 processor, 4GB of RAM, dual Broadcom GigE NICs bonded with Linux bonding driver, dual software RAID SATA disks for boot and swap.
The call trace included with the bug report is the only one that appears in the log with the "cut here" lines.

OK, that is the TCP code performing self-checks and finding an unexpected state.

I was just a bit concerned about the "segfault" part of the description. Because often when the kernel crashes this appears to the operator as a userspace segfault. But the above trace isn't a kernel crash - it's just a warning and the kernel does attept to fix things up in this case.

If however you were really seeing unexpected segfaults then it could be the case that the kernel is crashing. But I assume this is not the case, and that the text "Oops" does not appear in the logs.

Ilpo Järvinen

2008-05-21 20:18 UTC #4 lore raw

In reply to a message not in the archive

Quoted 1 line · Brian Vowell

Please forgive my lack of technical skills-- I am not a developer.

And I'm having problem in figuring out what is actually being reported here... so pleasy forgive my possibly stupid comments... :-)

Quoted 11 lines

The bug report referenced below recently occurred on a pretty busy file server of mine running Fedora 8 with a custom 2.6.25.4 kernel. The attached hardware RAID controller presents 12 LUNs, which were striped using the Linux mdadm tools, and then the Linux LVM was used to create a single logical volume. The filesystem used is XFS.
Since upgrading from 2.6.25.3 to 2.6.25.4, my log has shown a large number of errors that I don't possess the skills to diagnose which component is actually causing the errors. I can verify however, that the hardware is good. I have run memtest86 and the vendor's diagnostic tools and verified that everything is running well.

At least the TCP thing is known to be in core TCP but it's just hard to debug and that's why it hasn't yet been closed, no hw is suspect due to it. But this other stacktrace seems to be something unrelated to TCP...:

Quoted 42 lines

The errors in /var/log/messages look like this:

May 19 06:30:30 ishtar kernel: Call Trace:
May 19 06:30:30 ishtar kernel:  <IRQ>  [<ffffffff81075d35>]
__alloc_pages+0x33f/0x35a
May 19 06:30:30 ishtar kernel:  [<ffffffff8100e813>] do_IRQ+0x13e/0x15f
May 19 06:30:30 ishtar kernel:  [<ffffffff810934a4>] new_slab+0x3f/0x242
May 19 06:30:30 ishtar kernel:  [<ffffffff81093bba>]
__slab_alloc+0x212/0x43b
May 19 06:30:30 ishtar kernel:  [<ffffffff8128654c>]
__netdev_alloc_skb+0x29/0x43
May 19 06:30:30 ishtar kernel:  [<ffffffff8128654c>]
__netdev_alloc_skb+0x29/0x43
May 19 06:30:30 ishtar kernel:  [<ffffffff81094bd6>]
__kmalloc_node_track_caller+0x75/0xab
May 19 06:30:30 ishtar kernel:  [<ffffffff8128584a>] __alloc_skb+0x6a/0x133
May 19 06:30:30 ishtar kernel:  [<ffffffff8128654c>]
__netdev_alloc_skb+0x29/0x43
May 19 06:30:30 ishtar kernel:  [<ffffffff8123a405>]
tg3_alloc_rx_skb+0xc4/0x153
May 19 06:30:30 ishtar kernel:  [<ffffffff81241343>] tg3_poll+0x3be/0x7df
May 19 06:30:30 ishtar kernel:  [<ffffffff8128c2ce>]
net_rx_action+0xb6/0x1bf
May 19 06:30:30 ishtar kernel:  [<ffffffff8103919b>] __do_softirq+0x65/0xce
May 19 06:30:30 ishtar kernel:  [<ffffffff8100ce9c>] call_softirq+0x1c/0x28
May 19 06:30:30 ishtar kernel:  [<ffffffff8100e544>] do_softirq+0x2c/0x68
May 19 06:30:30 ishtar kernel:  [<ffffffff810390f2>] irq_exit+0x3f/0x83
May 19 06:30:30 ishtar kernel:  [<ffffffff8100e813>] do_IRQ+0x13e/0x15f
May 19 06:30:30 ishtar kernel:  [<ffffffff8100c221>] ret_from_intr+0x0/0xa
May 19 06:30:30 ishtar kernel:  <EOI>  [<ffffffff8100adc8>]
default_idle+0x0/0x55
May 19 06:30:30 ishtar kernel:  [<ffffffff8101c138>]
lapic_next_event+0x0/0xa
May 19 06:30:30 ishtar kernel:  [<ffffffff8100adc8>] default_idle+0x0/0x55
May 19 06:30:30 ishtar kernel:  [<ffffffff8100adf9>] default_idle+0x31/0x55
May 19 06:30:30 ishtar kernel:  [<ffffffff8100adf4>] default_idle+0x2c/0x55
May 19 06:30:30 ishtar kernel:  [<ffffffff8100adc8>] default_idle+0x0/0x55
May 19 06:30:30 ishtar kernel:  [<ffffffff8100ae94>] cpu_idle+0x77/0x9a

The hardware is an HP Proliant DL145G2, Dual Core Opteron 275 processor, 4GB of RAM, dual Broadcom GigE NICs bonded with Linux bonding driver, dual software RAID SATA disks for boot and swap.

Quoted 42 lines

The call trace included with the bug report is the only one that appears in the log with the "cut here" lines.
Quoted 35 lines · Andrew Morton
(switched to email. Please respond via emailed reply-to-all, not via the bugzilla web interface).
Quoted 3 lines · On Wed, 21 May 2008 02:45:59 -0700 (PDT) [email protected]:
http://bugzilla.kernel.org/show_bug.cgi?id=10767
Summary: Seg Fault Instead of Swapping
Strange description?
Quoted 14 lines
           Product: Networking
           Version: 2.5
     KernelVersion: 2.6.25.4
          Platform: All
        OS/Version: Linux
              Tree: Mainline
            Status: NEW
          Severity: normal
          Priority: P1
         Component: IPV4
        AssignedTo: [email protected]
        ReportedBy: [email protected]
Quoted 3 lines
May 20 13:11:00 ishtar kernel: ------------[ cut here ]------------
May 20 13:11:00 ishtar kernel: WARNING: at net/ipv4/tcp_input.c:2539
tcp_ack+0xd2b/0x191f()
In 2.6.25 this is
        if (WARN_ON(!tp->sacked_out && tp->fackets_out))
                tp->fackets_out = 0;

...This TCP warning isn't sign of a problem that would cause corruption of any kind (and the state inconsistency gets repaired there as well!), we're debugging this already with couple of other people, so unless you have some very good reproducer case you'll just have to wait a bit.

Signature · 1 line

i.

A message that is not in the archive (sent off-list or not yet received): [email protected]

Ilpo Järvinen

2008-05-23 10:25 UTC #6 lore raw

Quoted 4 lines · Brian Vowell

Quoted 3 lines · Ilpo Järvinen
On Wed, 21 May 2008, Brian Vowell wrote:

Quoted 8 lines

Quoted 4 lines
...This TCP warning isn't sign of a problem that would cause corruption of any kind (and the state inconsistency gets repaired there as well!), we're debugging this already with couple of other people, so unless you have some very good reproducer case you'll just have to wait a bit.
I don't mind waiting. I just thought that since this happened so quickly after upgrading to the 2.6.25.4 kernel that it might be something that was related to changes from 2.6.25.3.

It's just due to luck (that's what makes debugging it hard). There isn't anything even remotely related changed in 2.6.25.3 -> 2.6.25.4 :-). Of course, if you really want to you can always add the debug patch the other 2539-warning tracking people already use:

http://marc.info/?l=linux-netdev&m=120972551120080&w=2

It will add some expensive verifications that are run multiple times per ACK to validate TCP's internal consistency which is normally just "assumed" to be valid due to performance reasons. Please note what I said about CONFIG_LOG_BUF_SHIFT there so that the previous disaster doesn't repeat itself... :-) Then you just need to occassionally see if it has triggered (from kernel logs).

Quoted 4 lines

The only thing that I can do in regards to assisting is to provide info about what triggers the bug and/or provide access to my system to anyone who wants to take a closer look.

Quoted 13 lines

At the time the bug occurred, the system was running two I/O intensive applications. The first was the "xfs_fsr" tool to defragment the XFS filesystem (it was pushing about 25-30MB/sec to the array), and the rtorrent BitTorrent client, which was pulling down a Fedora ISO at about 25mbps, and writing to a SATA device, separate from the array where the XFS filesystem lives. In the past, I have seen the rtorrent client create oops errors when running within a Xen VM. This problem only occurred when the guest domU VM was running XFS for its root filesystem and the host dom0 that provided the filestore for the gues was also running XFS. (Running the guest on ext3 stops the oops errors). It may or may not be related to this error that I'm reporting, but considering that the rtorrent app is the same app that was running at the time of both segfaults and the oops errors, it makes me suspicious and I thought that I'd mention it.

All other details but torrent are most likely irrelevant, it could be that the added load has some significance to window behavior but that's not too likely to make difference. More important would be to know with which host torrent was communicating at the time of the WARNING, and even more importantly, what "special" happened between that host and your host in the network. Once that becomes known thing, this will be easy to reproduce and it might even be that the fix is then something dead obvious.

Quoted 5 lines

Just to be clear, the bug that I'm reporting is running on a clean system, with no Xen installed on it.
Otherwise, it's really like a bug in real life-- a small creature that is annoying but doesn't really harm anything.

The thing I'm still concerned in this report is the presence of the other stacktrace which seemed to not be TCP related. Could you confirm/list all the other problems than the WARNING net/ipv4/tcp_input.c:2539(+its stacktrace) that you have been seeing. ...I'm saying this because it might be worth of pursuing further.

Signature · 1 line

i.

A message that is not in the archive (sent off-list or not yet received): [email protected]

Ilpo Järvinen

2008-05-23 18:01 UTC #9 lore raw

Quoted 45 lines · Brian Vowell

I applied the ipv4 patch. Here are two traces that just showed up:

------------[ cut here ]------------
WARNING: at net/ipv4/tcp_input.c:3297 tcp_ack+0xd58/0xeba()
Modules linked in: dm_mirror dm_multipath dm_mod cfi_cmdset_0002 cfi_util

button jedec_probe cfi_probe gen_probe ck804xrom i2c_nforce2 mtd chipreg map_funcs k8temp sg hwmon pcspkr i2c_core serio_raw pata_amd cciss ata_generic pata_acpi sata_nv libata sd_mod scsi_mod raid456 async_xor async_memcpy async_tx xor raid1 uhci_hcd ohci_hcd ssb ehci_hcd [last
unloaded: scsi_wait_scan]
Pid: 0, comm: swapper Not tainted 2.6.25.4 #1

Call Trace:
 <IRQ>  [<ffffffff81034481>] warn_on_slowpath+0x51/0x63
 [<ffffffff8128cdaf>] dev_queue_xmit+0x25b/0x284
 [<ffffffff812ab9fa>] ip_queue_xmit+0x2cc/0x31f
 [<ffffffff812b0e3b>] sk_stream_alloc_skb+0x2f/0xd2
 [<ffffffff8104a1bb>] getnstimeofday+0x2f/0x83
 [<ffffffff812bb83d>] tcp_transmit_skb+0x775/0x7a4
 [<ffffffff812b760a>] tcp_ack+0xd58/0xeba
 [<ffffffff812ba74b>] tcp_rcv_established+0x7b9/0x8ce
 [<ffffffff812c05cd>] tcp_v4_do_rcv+0x2c2/0x48b
 [<ffffffff8129a07a>] __qdisc_run+0xf6/0x1c8
 [<ffffffff812ae376>] __inet_lookup_established+0xdf/0x17b
 [<ffffffff812c2528>] tcp_v4_rcv+0x6a3/0x700
 [<ffffffff812a7558>] ip_local_deliver+0xd4/0x18e
 [<ffffffff812a7b0d>] ip_rcv+0x4fb/0x53a
 [<ffffffff8128a2b7>] netif_receive_skb+0x351/0x372
 [<ffffffff8124150d>] tg3_poll+0x588/0x7df
 [<ffffffff8128c2ce>] net_rx_action+0xb6/0x1bf
 [<ffffffff8103919b>] __do_softirq+0x65/0xce
 [<ffffffff8100ce9c>] call_softirq+0x1c/0x28
 [<ffffffff8100e544>] do_softirq+0x2c/0x68
 [<ffffffff810390f2>] irq_exit+0x3f/0x83
 [<ffffffff8100e813>] do_IRQ+0x13e/0x15f
 [<ffffffff8100c221>] ret_from_intr+0x0/0xa
 <EOI>  [<ffffffff8100adc8>] default_idle+0x0/0x55
 [<ffffffff8101c138>] lapic_next_event+0x0/0xa
 [<ffffffff8100adc8>] default_idle+0x0/0x55
 [<ffffffff8100adf9>] default_idle+0x31/0x55
 [<ffffffff8100adf4>] default_idle+0x2c/0x55
 [<ffffffff8100adc8>] default_idle+0x0/0x55
 [<ffffffff8100ae94>] cpu_idle+0x77/0x9a

---[ end trace aae73dd976dfcd54 ]---

Quoted 3 lines

TCP wq(s) S <
TCP wq(h) ++h-----+-----+---<
l0 s1 f2 p18 seq: wq1288576867, su1288576867 hs1288579763 sn1288602883

Aha, it seems you got TCP into the invalid state which I recently added check for :-), I'll try to figure out how that could still happen (I think I tried to find such code path already earlier but it seems that there's still something I've overlooked). Though this is not directly going to cause the 2539 WARNING, yet it could, after some other (probably rare condition) possibly lead to that as well if this invariant is assumed to hold while doing some state manipulation elsewhere in TCP (though I think that's not too likely). In case you don't see them too often, you can well continue with the patch in order to find the cause for 2539 as well (and just ignore those occassional net/ipv4/tcp_input.c:3297 ones for now).

Thanks,

Signature · 1 line

i.

A message that is not in the archive (sent off-list or not yet received): [email protected]

Ilpo Järvinen

2008-05-24 08:57 UTC #11 lore raw

Quoted 13 lines · Brian Vowell

Quoted 11 lines
Aha, it seems you got TCP into the invalid state which I recently added check for :-), I'll try to figure out how that could still happen (I think I tried to find such code path already earlier but it seems that there's still something I've overlooked). Though this is not directly going to cause the 2539 WARNING, yet it could, after some other (probably rare condition) possibly lead to that as well if this invariant is assumed to hold while doing some state manipulation elsewhere in TCP (though I think that's not too likely). In case you don't see them too often, you can well continue with the patch in order to find the cause for 2539 as well (and just ignore those occassional net/ipv4/tcp_input.c:3297 ones for now).

Quoted 1 line

Do you want me to continue emailing these traces as they appear in my logs?

...Yes, in case you get something different than the WARNING at 3297. I have at least one suspect already which could lead to that 3297 :-).

Signature · 1 line

i.

A message that is not in the archive (sent off-list or not yet received): [email protected]

Ilpo Järvinen

2008-05-26 11:24 UTC #13 lore raw

Quoted 1 line · Brian Vowell

Here are more traces. They all are warnings at 3297.

Hmm, likely fix to that included below (you might not be able to reproduce it anymore though because it's very sensitive to network behavior, ie., in case the peer you were communicating with isn't there any more the necessary events simply won't happen).

There seems to be yet another candidate in tcp_fastretrans_alert() that could cause it but it's extremely unlikely to occur in practice. ...I'll fix this one separately later on.

And this isn't exactly there problem we were tracking for but it's nice that it showed up as well (so you might want to keep the debug patch still applied too)... :-)

Signature · 38 lines

 i.


--
[PATCH] [TCP]: Fix inconsistency source (CA_Open only when !tcp_left_out(tp))

It is possible that this skip path causes TCP to end up into an
invalid state where ca_state was left to CA_Open while some
segments already came into sacked_out. If next valid ACK doesn't
contain new SACK information TCP fails to enter into
tcp_fastretrans_alert(). Thus at least high_seq is set
incorrectly to a too high seqno because some new data segments
could be sent in between (and also, limited transmit is not
being correctly invoked there). Reordering in both directions
can easily cause this situation to occur.

I guess we would want to use tcp_moderate_cwnd(tp) there as well
as it may be possible to use this to trigger oversized burst to
network by sending an old ACK with huge amount of SACK info, but
I'm a bit unsure about its effects (mainly to FlightSize), so to
be on the safe side I just currently fixed it minimally to keep
TCP's state consistent (obviously, such nasty ACKs have been
possible this far). Though it seems that FlightSize is already
underestimated by some amount, so probably on the long term we
might want to trigger recovery there too, if appropriate, to make
FlightSize calculation to resemble reality at the time when the
losses where discovered (but such change scares me too much now
and requires some more thinking anyway how to do that as it
likely involves some code shuffling).

This bug was found by Brian Vowell while running my TCP debug
patch to find cause of another TCP issue (fackets_out
miscount).

Signed-off-by: Ilpo Järvinen <[email protected]>
---
 net/ipv4/tcp_input.c |   29 +++++++++++++++++++----------
 1 files changed, 19 insertions(+), 10 deletions(-)

net/ipv4/tcp_input.c +19 ~~-10~~

index d9936a2..be53021 100644
@@ -2483,6 +2483,20 @@ static inline void tcp_complete_cwr(struct sock *sk)
 	tcp_ca_event(sk, CA_EVENT_COMPLETE_CWR);
 }
 
+static void tcp_try_keep_open(struct sock *sk)
+{
+	struct tcp_sock *tp = tcp_sk(sk);
+	int state = TCP_CA_Open;
+
+	if (tcp_left_out(tp) || tp->retrans_out || tp->undo_marker)
+		state = TCP_CA_Disorder;
+
+	if (inet_csk(sk)->icsk_ca_state != state) {
+		tcp_set_ca_state(sk, state);
+		tp->high_seq = tp->snd_nxt;
+	}
+}
+
 static void tcp_try_to_open(struct sock *sk, int flag)
 {
 	struct tcp_sock *tp = tcp_sk(sk);

@@ -2496,15 +2510,7 @@ static void tcp_try_to_open(struct sock *sk, int flag)
 		tcp_enter_cwr(sk, 1);
 
 	if (inet_csk(sk)->icsk_ca_state != TCP_CA_CWR) {
-		int state = TCP_CA_Open;
-
-		if (tcp_left_out(tp) || tp->retrans_out || tp->undo_marker)
-			state = TCP_CA_Disorder;
-
-		if (inet_csk(sk)->icsk_ca_state != state) {
-			tcp_set_ca_state(sk, state);
-			tp->high_seq = tp->snd_nxt;
-		}
+		tcp_try_keep_open(sk);
 		tcp_moderate_cwnd(tp);
 	} else {
 		tcp_cwnd_down(sk, flag);

@@ -3312,8 +3318,11 @@ no_queue:
 	return 1;
 
 old_ack:
-	if (TCP_SKB_CB(skb)->sacked)
+	if (TCP_SKB_CB(skb)->sacked) {
 		tcp_sacktag_write_queue(sk, skb, prior_snd_una);
+		if (icsk->icsk_ca_state == TCP_CA_Open)
+			tcp_try_keep_open(sk);
+	}
 
 uninteresting_ack:
 	SOCK_DEBUG(sk, "Ack %u out of %u:%u\n", ack, tp->snd_una, tp->snd_nxt);

Signature · 1 line

1.5.2.2

David Miller

maintainer

2008-06-03 23:35 UTC #14 lore raw

From: "Ilpo_Järvinen" <[email protected]>
Date: Mon, 26 May 2008 14:24:33 +0300 (EEST)

Ilpo, do you want me to apply this to net-2.6?

Quoted 31 lines

[PATCH] [TCP]: Fix inconsistency source (CA_Open only when !tcp_left_out(tp))
It is possible that this skip path causes TCP to end up into an invalid state where ca_state was left to CA_Open while some segments already came into sacked_out. If next valid ACK doesn't contain new SACK information TCP fails to enter into tcp_fastretrans_alert(). Thus at least high_seq is set incorrectly to a too high seqno because some new data segments could be sent in between (and also, limited transmit is not being correctly invoked there). Reordering in both directions can easily cause this situation to occur.
I guess we would want to use tcp_moderate_cwnd(tp) there as well as it may be possible to use this to trigger oversized burst to network by sending an old ACK with huge amount of SACK info, but I'm a bit unsure about its effects (mainly to FlightSize), so to be on the safe side I just currently fixed it minimally to keep TCP's state consistent (obviously, such nasty ACKs have been possible this far). Though it seems that FlightSize is already underestimated by some amount, so probably on the long term we might want to trigger recovery there too, if appropriate, to make FlightSize calculation to resemble reality at the time when the losses where discovered (but such change scares me too much now and requires some more thinking anyway how to do that as it likely involves some code shuffling).
This bug was found by Brian Vowell while running my TCP debug patch to find cause of another TCP issue (fackets_out miscount).
Signed-off-by Ilpo Järvinen <[email protected]>

Ilpo Järvinen

2008-06-04 07:12 UTC #15 lore raw

Quoted 4 lines · David Miller

From: "Ilpo_Järvinen" <[email protected]>
Date: Mon, 26 May 2008 14:24:33 +0300 (EEST)
Ilpo, do you want me to apply this to net-2.6?

Yes thanks, it is necessary to keep the state consistent (it also explains some .22/23 time left_out warn_ons too which were mysterious back then). Also -stable (I guess it would be necessary to almost any older stable too though some older ones might want to sync left_out on that same place too).

It was nice that this path was also triggered while running the TCP debug patch (I haven't gotten a one in here), otherwise we would never have known though I started to suspect that such path existed once I tried to analyze those left_out problems (before it got dropped altogether), but I just couldn't find the problem because it lies on such "error path" which was too easy to overlook.

I also finally have found the cause to the !sacked_out && fackets_out trap :-). ...I'll post the fix to that later today to relevant parties.

Quoted 1 line

Quoted 1 line
[PATCH] [TCP]: Fix inconsistency source (CA_Open only when !tcp_left_out(tp))

Signature · 1 line

i.

David Miller

maintainer

2008-06-04 18:20 UTC #16 lore raw

From: "Ilpo_Järvinen" <[email protected]>
Date: Wed, 4 Jun 2008 10:12:04 +0300 (EEST)

Quoted 13 lines · David Miller

Quoted 5 lines
From: "Ilpo_Järvinen" <[email protected]>
Date: Mon, 26 May 2008 14:24:33 +0300 (EEST)
Ilpo, do you want me to apply this to net-2.6?
Yes thanks, it is necessary to keep the state consistent (it also explains some .22/23 time left_out warn_ons too which were mysterious back then). Also -stable (I guess it would be necessary to almost any older stable too though some older ones might want to sync left_out on that same place too).

Quoted 6 lines

It was nice that this path was also triggered while running the TCP debug patch (I haven't gotten a one in here), otherwise we would never have known though I started to suspect that such path existed once I tried to analyze those left_out problems (before it got dropped altogether), but I just couldn't find the problem because it lies on such "error path" which was too easy to overlook.

Ok I've add the patch to net-2.6, thanks!

Quoted 2 lines

I also finally have found the cause to the !sacked_out && fackets_out trap :-). ...I'll post the fix to that later today to relevant parties.

I'll have a look at this too :-)

Thanks for all of your incredible work on TCP bug fixing!

Ilpo Järvinen

2008-05-26 11:33 UTC #17 lore raw

In reply to a message not in the archive

Quoted 6 lines · Brian Vowell

Here are some of the others that show in the logs:
This one repeats four times, and then again multiple times every minute afterwards for about 30 minutes.
May 18 19:31:00 ishtar kernel: pdflush: page allocation failure. order:3,
mode:0x4020

I think that the problem here is that tg3 tries to allocate a large contiguous memory block which isn't available.

Quoted 13 lines

May 18 19:31:00 ishtar kernel: Pid: 15300, comm: pdflush Not tainted
2.6.25.4 #1
May 18 19:31:00 ishtar kernel:
May 18 19:31:00 ishtar kernel: Call Trace:
May 18 19:31:00 ishtar kernel:  <IRQ>  [<ffffffff81075d35>]
__alloc_pages+0x33f/0x35a
May 18 19:31:00 ishtar kernel:  [<ffffffff810934a4>] new_slab+0x3f/0x242
May 18 19:31:00 ishtar kernel:  [<ffffffff81093bba>]
__slab_alloc+0x212/0x43b
May 18 19:31:00 ishtar kernel:  [<ffffffff8128654c>]
__netdev_alloc_skb+0x29/0x43
May 18 19:31:00 ishtar kernel:  [<ffffffff8128654c>]

__netdev_alloc_skb+0x29/0x43

Quoted 8 lines

May 18 19:31:00 ishtar kernel:  [<ffffffff81094bd6>]
__kmalloc_node_track_caller+0x75/0xab
May 18 19:31:00 ishtar kernel:  [<ffffffff8128584a>] __alloc_skb+0x6a/0x133
May 18 19:31:00 ishtar kernel:  [<ffffffff8128654c>]
__netdev_alloc_skb+0x29/0x43
May 18 19:31:00 ishtar kernel:  [<ffffffff8123a405>]
tg3_alloc_rx_skb+0xc4/0x153
May 18 19:31:00 ishtar kernel:  [<ffffffff81241343>] tg3_poll+0x3be/0x7df

...but I'm probably not much of help with it.

Signature · 1 line

i.