* Re: WARNING: at net/ipv4/tcp_input.c:2054 tcp_mark_head_lost() [not found] <858077.97160.qm@web39709.mail.mud.yahoo.com> @ 2008-02-23 8:03 ` Andrew Morton 2008-02-27 9:29 ` Ilpo Järvinen 0 siblings, 1 reply; 20+ messages in thread From: Andrew Morton @ 2008-02-23 8:03 UTC (permalink / raw) To: Giangiacomo Mariotti; +Cc: linux-kernel, netdev (cc netdev) On Wed, 20 Feb 2008 20:04:39 -0800 (PST) Giangiacomo Mariotti <giangiacomo_mariotti@yahoo.com> wrote: > This is what I got with dmesg : > > [ 266.978695] WARNING: at net/ipv4/tcp_input.c:2054 tcp_mark_head_lost() > [ 266.978701] Pid: 0, comm: swapper Not tainted 2.6.24.2-my001 #1 > [ 266.978703] > [ 266.978704] Call Trace: > [ 266.978706] <IRQ> [<ffffffff80426981>] tcp_ack+0x16d8/0x197f > [ 266.978721] [<ffffffff8022e72f>] __wake_up+0x38/0x4e > [ 266.978727] [<ffffffff804295ef>] tcp_rcv_established+0xe2/0x8cb > [ 266.978732] [<ffffffff8042f56f>] tcp_v4_do_rcv+0x30/0x39c > [ 266.978738] [<ffffffff80431d29>] tcp_v4_rcv+0x99b/0xa06 > [ 266.978743] [<ffffffff803f2c95>] __netdev_alloc_skb+0x29/0x43 > [ 266.978749] [<ffffffff80416d21>] ip_local_deliver_finish+0x152/0x212 > [ 266.978753] [<ffffffff80416bac>] ip_rcv_finish+0x2f8/0x31b > [ 266.978758] [<ffffffff803f6c42>] netif_receive_skb+0x3ae/0x3d1 > [ 266.978763] [<ffffffff8037398f>] rtl8169_rx_interrupt+0x45f/0x53e > [ 266.978768] [<ffffffff8037405b>] rtl8169_poll+0x36/0x16a > [ 266.978773] [<ffffffff803f8ca7>] net_rx_action+0xb7/0x1f3 > [ 266.978778] [<ffffffff8023a3a5>] __do_softirq+0x65/0xce > [ 266.978782] [<ffffffff8020b0d2>] default_idle+0x0/0x3d > [ 266.978786] [<ffffffff8020d09c>] call_softirq+0x1c/0x28 > [ 266.978789] [<ffffffff8020e4f0>] do_softirq+0x2c/0x7d > [ 266.978792] [<ffffffff8023a2fb>] irq_exit+0x3f/0x84 > [ 266.978794] [<ffffffff8020e729>] do_IRQ+0xb6/0xd5 > [ 266.978797] [<ffffffff8020b0d2>] default_idle+0x0/0x3d > [ 266.978800] [<ffffffff8020c421>] ret_from_intr+0x0/0xa > [ 266.978801] <EOI> [<ffffffff8020b0fb>] default_idle+0x29/0x3d > [ 266.978809] [<ffffffff8020b1a2>] cpu_idle+0x93/0xbb > [ 266.978813] [<ffffffff805cfa4b>] start_kernel+0x2bb/0x2c7 > [ 266.978818] [<ffffffff805cf123>] _sinittext+0x123/0x12a > [ 266.978821] > > This though didn't cause any user-visible problem. > > .config file : ^ permalink raw reply [flat|nested] 20+ messages in thread
* Re: WARNING: at net/ipv4/tcp_input.c:2054 tcp_mark_head_lost() 2008-02-23 8:03 ` WARNING: at net/ipv4/tcp_input.c:2054 tcp_mark_head_lost() Andrew Morton @ 2008-02-27 9:29 ` Ilpo Järvinen 2008-02-27 18:56 ` Guillaume Chazarain 0 siblings, 1 reply; 20+ messages in thread From: Ilpo Järvinen @ 2008-02-27 9:29 UTC (permalink / raw) To: Giangiacomo Mariotti; +Cc: LKML, Netdev, Andrew Morton On Sat, 23 Feb 2008, Andrew Morton wrote: > > (cc netdev) > > On Wed, 20 Feb 2008 20:04:39 -0800 (PST) Giangiacomo Mariotti <giangiacomo_mariotti@yahoo.com> wrote: > > > This is what I got with dmesg : > > > > [ 266.978695] WARNING: at net/ipv4/tcp_input.c:2054 tcp_mark_head_lost() > > [ 266.978701] Pid: 0, comm: swapper Not tainted 2.6.24.2-my001 #1 > > [ 266.978703] > > [ 266.978704] Call Trace: > > [ 266.978706] <IRQ> [<ffffffff80426981>] tcp_ack+0x16d8/0x197f > > [ 266.978721] [<ffffffff8022e72f>] __wake_up+0x38/0x4e > > [ 266.978727] [<ffffffff804295ef>] tcp_rcv_established+0xe2/0x8cb > > [ 266.978732] [<ffffffff8042f56f>] tcp_v4_do_rcv+0x30/0x39c > > [ 266.978738] [<ffffffff80431d29>] tcp_v4_rcv+0x99b/0xa06 > > [ 266.978743] [<ffffffff803f2c95>] __netdev_alloc_skb+0x29/0x43 > > [ 266.978749] [<ffffffff80416d21>] ip_local_deliver_finish+0x152/0x212 > > [ 266.978753] [<ffffffff80416bac>] ip_rcv_finish+0x2f8/0x31b > > [ 266.978758] [<ffffffff803f6c42>] netif_receive_skb+0x3ae/0x3d1 > > [ 266.978763] [<ffffffff8037398f>] rtl8169_rx_interrupt+0x45f/0x53e > > [ 266.978768] [<ffffffff8037405b>] rtl8169_poll+0x36/0x16a > > [ 266.978773] [<ffffffff803f8ca7>] net_rx_action+0xb7/0x1f3 > > [ 266.978778] [<ffffffff8023a3a5>] __do_softirq+0x65/0xce > > [ 266.978782] [<ffffffff8020b0d2>] default_idle+0x0/0x3d > > [ 266.978786] [<ffffffff8020d09c>] call_softirq+0x1c/0x28 > > [ 266.978789] [<ffffffff8020e4f0>] do_softirq+0x2c/0x7d > > [ 266.978792] [<ffffffff8023a2fb>] irq_exit+0x3f/0x84 > > [ 266.978794] [<ffffffff8020e729>] do_IRQ+0xb6/0xd5 > > [ 266.978797] [<ffffffff8020b0d2>] default_idle+0x0/0x3d > > [ 266.978800] [<ffffffff8020c421>] ret_from_intr+0x0/0xa > > [ 266.978801] <EOI> [<ffffffff8020b0fb>] default_idle+0x29/0x3d > > [ 266.978809] [<ffffffff8020b1a2>] cpu_idle+0x93/0xbb > > [ 266.978813] [<ffffffff805cfa4b>] start_kernel+0x2bb/0x2c7 > > [ 266.978818] [<ffffffff805cf123>] _sinittext+0x123/0x12a > > [ 266.978821] > > Are you able to reproduce this in any way? I did in the past a debug patch that verifies TCP's write queue state by the hard way, ie., by bruteforce walking often enough to catch inconsistencies early enough to find out the root cause. I'll try to find that for you after I first go through the 2.6.24.2's code once again (but I'm pretty busy at this moment, so it might take a small while)... > > This though didn't cause any user-visible problem. Usually it's very insignificant to see them, unless you have them in very large quantities (it usually triggers for the same occurance in a number of places where that very same thing is being checked, thus having many of them in a row once is not what I mean here). Were there Leak printouts as well a bit after that? If not, this is triggered with either non-SACK TCP or it is a genuine S+L bits bug. -- i. ^ permalink raw reply [flat|nested] 20+ messages in thread
* Re: WARNING: at net/ipv4/tcp_input.c:2054 tcp_mark_head_lost() 2008-02-27 9:29 ` Ilpo Järvinen @ 2008-02-27 18:56 ` Guillaume Chazarain 2008-02-27 19:29 ` Ilpo Järvinen 0 siblings, 1 reply; 20+ messages in thread From: Guillaume Chazarain @ 2008-02-27 18:56 UTC (permalink / raw) To: Ilpo Järvinen; +Cc: Giangiacomo Mariotti, LKML, Netdev, Andrew Morton [-- Attachment #1: Type: text/plain, Size: 3117 bytes --] Hi Ilpo, On Wed, Feb 27, 2008 at 10:29 AM, Ilpo Järvinen <ilpo.jarvinen@helsinki.fi> wrote: > I did in the past a debug patch > that verifies TCP's write queue state by the hard way, ie., by bruteforce > walking often enough to catch inconsistencies early enough to find out > the root cause. Are you talking about this one: http://marc.info/?l=linux-netdev&m=119482084511178 ? I attached a forward port to current git. I am using this patch, and caught this maybe related error while Bittorrenting: KERNEL: assertion (packets <= tp->packets_out) failed at /home/g/linux-2.6/net/ipv4/tcp_input.c (2145) KERNEL: assertion (packets <= tp->packets_out) failed at /home/g/linux-2.6/net/ipv4/tcp_input.c (2145) ------------[ cut here ]------------ WARNING: at /home/g/linux-2.6/net/ipv4/tcp_input.c:2515 tcp_fastretrans_alert+0xa5/0xa4f() Modules linked in: radeon drm acpi_cpufreq lm90 hwmon binfmt_misc dm_mirror dm_mod snd_intel8x0m snd_intel8x0 snd_seq_dummy snd_ac97_codec ac97_bus snd_seq_oss snd_seq_midi_event snd_seq snd_seq_device snd_pcm_oss snd_mixer_oss snd_pcm snd_timer snd ohci1394 ieee1394 hci_usb ipw2200 bluetooth usbhid ieee80211 firewire_ohci soundcore hid snd_page_alloc sg rtc_cmos i2c_i801 iTCO_wdt serio_raw firewire_core button ac asus_laptop i2c_core rtc_core crc_itu_t irda crc_ccitt battery skge led_class rtc_lib pcspkr ieee80211_crypt sdhci mmc_core sr_mod cdrom pata_acpi uhci_hcd ohci_hcd ehci_hcd Pid: 0, comm: swapper Not tainted 2.6.25-rc2-gc-00243-g54a8145 #379 [<c011aff0>] warn_on_slowpath+0x41/0x51 [<c02e0ae0>] ? tcp_sacktag_walk+0x67/0x2a6 [<c02e9c9f>] ? tcp_v4_send_check+0x77/0xb1 [<c02e5aa2>] ? tcp_transmit_skb+0x644/0x677 [<c0169634>] ? __slab_free+0x56/0x262 [<c02b5738>] ? skb_release_data+0x84/0x89 [<c016a004>] ? kfree+0x6e/0x7a [<c02b5738>] ? skb_release_data+0x84/0x89 [<c02e0046>] tcp_fastretrans_alert+0xa5/0xa4f [<c02e2089>] tcp_ack+0xba6/0xcf9 [<c02e4740>] tcp_rcv_established+0xdb/0x5fb [<c02e960e>] tcp_v4_do_rcv+0x28/0x188 [<c02ead20>] tcp_v4_rcv+0x5a2/0x607 [<f8985daf>] ? ipw_rx+0x12b5/0x12bd [ipw2200] [<c02d4165>] ip_local_deliver_finish+0xda/0x16a [<c02d4543>] ip_local_deliver+0x64/0x6d [<c02d406c>] ip_rcv_finish+0x244/0x263 [<c02d44c1>] ip_rcv+0x1d2/0x1f0 [<c02b9e86>] netif_receive_skb+0x34d/0x3d1 [<c02bbc2f>] process_backlog+0x5b/0xa5 [<c02bb849>] net_rx_action+0x86/0x166 [<c011f418>] __do_softirq+0x38/0x7a [<c0106327>] do_softirq+0x3e/0x72 [<c014a0e3>] ? handle_fasteoi_irq+0x0/0xbd [<c011f364>] irq_exit+0x28/0x61 [<c01063f0>] do_IRQ+0x95/0xaa [<c0105293>] common_interrupt+0x23/0x28 [<c014007b>] ? cgroup_scan_tasks+0x73/0x15b [<c0110000>] ? io_apic_set_pci_routing+0x2b/0x119 [<c023a59c>] ? acpi_idle_enter_simple+0x15b/0x1c7 [<c023a6bb>] acpi_idle_enter_bm+0xb3/0x2cc [<c02acc2b>] cpuidle_idle_call+0x4c/0x71 [<c02acbdf>] ? cpuidle_idle_call+0x0/0x71 [<c0103570>] cpu_idle+0x5a/0x87 [<c0311af8>] rest_init+0x5c/0x5e ======================= ---[ end trace c3302487bda6288d ]--- I attached the full dmesg, but I don't think there is any output caused by the TCP_DEBUG patch. Cheers. -- Guillaume [-- Attachment #2: TCP_DEBUG --] [-- Type: application/octet-stream, Size: 6958 bytes --] diff --git a/include/net/tcp.h b/include/net/tcp.h index 7de4ea3..c8fd034 100644 --- a/include/net/tcp.h +++ b/include/net/tcp.h @@ -272,6 +272,8 @@ DECLARE_SNMP_STAT(struct tcp_mib, tcp_statistics); #define TCP_ADD_STATS_BH(field, val) SNMP_ADD_STATS_BH(tcp_statistics, field, val) #define TCP_ADD_STATS_USER(field, val) SNMP_ADD_STATS_USER(tcp_statistics, field, val) +extern void tcp_verify_lost(struct sock *sk); + extern void tcp_v4_err(struct sk_buff *skb, u32); extern void tcp_shutdown (struct sock *sk, int how); diff --git a/net/ipv4/tcp_input.c b/net/ipv4/tcp_input.c index 19c449f..681ab1c 100644 --- a/net/ipv4/tcp_input.c +++ b/net/ipv4/tcp_input.c @@ -1604,6 +1604,7 @@ advance_sp: tcp_mark_lost_retrans(sk); tcp_verify_left_out(tp); + tcp_verify_lost(sk); if ((reord < tp->fackets_out) && ((icsk->icsk_ca_state != TCP_CA_Loss) || tp->undo_marker) && @@ -1647,6 +1648,7 @@ static void tcp_add_reno_sack(struct sock *sk) tp->sacked_out++; tcp_check_reno_reordering(sk, 0); tcp_verify_left_out(tp); + tcp_verify_lost(sk); } /* Account for ACK, ACKing some data in Reno Recovery phase. */ @@ -1664,6 +1666,7 @@ static void tcp_remove_reno_sacks(struct sock *sk, int acked) } tcp_check_reno_reordering(sk, acked); tcp_verify_left_out(tp); + tcp_verify_lost(sk); } static inline void tcp_reset_reno_sack(struct tcp_sock *tp) @@ -1765,6 +1768,7 @@ void tcp_enter_frto(struct sock *sk) tp->retrans_out -= tcp_skb_pcount(skb); } tcp_verify_left_out(tp); + tcp_verify_lost(sk); /* Too bad if TCP was application limited */ tp->snd_cwnd = min(tp->snd_cwnd, tcp_packets_in_flight(tp) + 1); @@ -1827,6 +1831,7 @@ static void tcp_enter_frto_loss(struct sock *sk, int allowed_segments, int flag) } } tcp_verify_left_out(tp); + tcp_verify_lost(sk); tp->snd_cwnd = tcp_packets_in_flight(tp) + allowed_segments; tp->snd_cwnd_cnt = 0; @@ -1912,6 +1917,7 @@ void tcp_enter_loss(struct sock *sk, int how) } } tcp_verify_left_out(tp); + tcp_verify_lost(sk); tp->reordering = min_t(unsigned int, tp->reordering, sysctl_tcp_reordering); @@ -2167,6 +2173,7 @@ static void tcp_mark_head_lost(struct sock *sk, int packets, int fast_rexmit) } } tcp_verify_left_out(tp); + tcp_verify_lost(sk); } /* Account newly detected lost packet(s) */ @@ -2216,6 +2223,7 @@ static void tcp_update_scoreboard(struct sock *sk, int fast_rexmit) tp->scoreboard_skb_hint = skb; tcp_verify_left_out(tp); + tcp_verify_lost(sk); } } @@ -2431,6 +2439,7 @@ static void tcp_try_to_open(struct sock *sk, int flag) struct tcp_sock *tp = tcp_sk(sk); tcp_verify_left_out(tp); + tcp_verify_lost(sk); if (tp->retrans_out == 0) tp->retrans_stamp = 0; @@ -2526,6 +2535,7 @@ static void tcp_fastretrans_alert(struct sock *sk, int pkts_acked, int flag) /* D. Check consistency of the current state. */ tcp_verify_left_out(tp); + tcp_verify_lost(sk); /* E. Check state exit conditions. State can be terminated * when high_seq is ACKed. */ @@ -2645,6 +2655,12 @@ static void tcp_fastretrans_alert(struct sock *sk, int pkts_acked, int flag) if (do_lost || (tcp_is_fack(tp) && tcp_head_timedout(sk))) tcp_update_scoreboard(sk, fast_rexmit); tcp_cwnd_down(sk, flag); + + if (WARN_ON(tcp_write_queue_head(sk) == NULL)) + return; + if (WARN_ON(!tp->packets_out)) + return; + tcp_xmit_retransmit_queue(sk); } @@ -2847,6 +2863,8 @@ static int tcp_clean_rtx_queue(struct sock *sk, int prior_fackets) sk_wmem_free_skb(sk, skb); tcp_clear_all_retrans_hints(tp); } + + tcp_verify_lost(sk); if (skb && (TCP_SKB_CB(skb)->sacked & TCPCB_SACKED_ACKED)) flag |= FLAG_SACK_RENEGING; @@ -2890,6 +2908,8 @@ static int tcp_clean_rtx_queue(struct sock *sk, int prior_fackets) #if FASTRETRANS_DEBUG > 0 BUG_TRAP((int)tp->sacked_out >= 0); BUG_TRAP((int)tp->lost_out >= 0); + if (tp->lost_out > tp->packets_out) + printk(KERN_ERR "Lost underflowed to %u\n", tp->lost_out); BUG_TRAP((int)tp->retrans_out >= 0); if (!tp->packets_out && tcp_is_sack(tp)) { icsk = inet_csk(sk); @@ -3061,6 +3081,7 @@ static int tcp_process_frto(struct sock *sk, int flag) struct tcp_sock *tp = tcp_sk(sk); tcp_verify_left_out(tp); + tcp_verify_lost(sk); /* Duplicate the behavior from Loss state (fastretrans_alert) */ if (flag & FLAG_DATA_ACKED) diff --git a/net/ipv4/tcp_ipv4.c b/net/ipv4/tcp_ipv4.c index 00156bf..410aada 100644 --- a/net/ipv4/tcp_ipv4.c +++ b/net/ipv4/tcp_ipv4.c @@ -108,6 +108,25 @@ struct inet_hashinfo __cacheline_aligned tcp_hashinfo = { .lhash_wait = __WAIT_QUEUE_HEAD_INITIALIZER(tcp_hashinfo.lhash_wait), }; +void tcp_verify_lost(struct sock *sk) +{ + struct tcp_sock *tp = tcp_sk(sk); + u32 lost = 0; + struct sk_buff *skb; + + tcp_for_write_queue(skb, sk) { + if (skb == tcp_send_head(sk)) + break; + if (TCP_SKB_CB(skb)->sacked & TCPCB_LOST) + lost += tcp_skb_pcount(skb); + } + + if (WARN_ON(lost != tp->lost_out)) { + printk(KERN_ERR "Lost: %u vs %u, %u (%d)\n", lost, tp->lost_out, + tp->packets_out, tcp_is_sack(tp)); + } +} + static inline __u32 tcp_v4_init_sequence(struct sk_buff *skb) { return secure_tcp_sequence_number(ip_hdr(skb)->daddr, diff --git a/net/ipv4/tcp_output.c b/net/ipv4/tcp_output.c index ed750f9..586660a 100644 --- a/net/ipv4/tcp_output.c +++ b/net/ipv4/tcp_output.c @@ -790,6 +790,8 @@ int tcp_fragment(struct sock *sk, struct sk_buff *skb, u32 len, skb_header_release(buff); tcp_insert_write_queue_after(skb, buff, sk); + tcp_verify_lost(sk); + return 0; } @@ -1459,10 +1461,12 @@ static int tcp_write_xmit(struct sock *sk, unsigned int mss_now, int nonagle) /* Do MTU probing. */ if ((result = tcp_mtu_probe(sk)) == 0) { + tcp_verify_lost(sk); return 0; } else if (result > 0) { sent_pkts = 1; } + tcp_verify_lost(sk); while ((skb = tcp_send_head(sk))) { unsigned int limit; @@ -1764,6 +1768,7 @@ static void tcp_retrans_try_collapse(struct sock *sk, struct sk_buff *skb, tcp_clear_retrans_hints_partial(tp); sk_wmem_free_skb(sk, next_skb); + tcp_verify_lost(sk); } /* Do a simple retransmit without using the backoff mechanisms in @@ -1794,6 +1799,8 @@ void tcp_simple_retransmit(struct sock *sk) } } } + + tcp_verify_lost(sk); tcp_clear_all_retrans_hints(tp); @@ -1815,6 +1822,8 @@ void tcp_simple_retransmit(struct sock *sk) tcp_set_ca_state(sk, TCP_CA_Loss); } tcp_xmit_retransmit_queue(sk); + + tcp_verify_lost(sk); } /* This retransmits one SKB. Policy decisions and retransmit queue @@ -1996,6 +2005,8 @@ void tcp_xmit_retransmit_queue(struct sock *sk) } } } + + tcp_verify_lost(sk); /* OK, demanded retransmission is finished. */ @@ -2054,6 +2065,8 @@ void tcp_xmit_retransmit_queue(struct sock *sk) NET_INC_STATS_BH(LINUX_MIB_TCPFORWARDRETRANS); } + + tcp_verify_lost(sk); } /* Send a fin. The caller locks the socket for us. This cannot be [-- Attachment #3: dmesg-tcp --] [-- Type: application/octet-stream, Size: 52493 bytes --] Linux version 2.6.25-rc2-gc-00243-g54a8145 (g@localhost.localdomain) (gcc version 4.1.2 20070925 (Red Hat 4.1.2-33)) #379 PREEMPT Tue Feb 19 19:57:06 CET 2008 BIOS-provided physical RAM map: BIOS-e820: 0000000000000000 - 000000000009fc00 (usable) BIOS-e820: 000000000009fc00 - 00000000000a0000 (reserved) BIOS-e820: 00000000000e0000 - 0000000000100000 (reserved) BIOS-e820: 0000000000100000 - 000000007ffa0000 (usable) BIOS-e820: 000000007ffa0000 - 000000007ffb0000 (ACPI data) BIOS-e820: 000000007ffb0000 - 000000007fff0000 (ACPI NVS) BIOS-e820: 000000007fff0000 - 0000000080000000 (reserved) BIOS-e820: 00000000ffb80000 - 0000000100000000 (reserved) 1151MB HIGHMEM available. 896MB LOWMEM available. Scan SMP from c0000000 for 1024 bytes. Scan SMP from c009fc00 for 1024 bytes. Scan SMP from c00f0000 for 65536 bytes. found SMP MP-table at [c00ff780] 000ff780 Reserving 64MB of memory at 16MB for crashkernel (System RAM: 2042MB) Entering add_active_range(0, 0, 524192) 0 entries of 256 used Zone PFN ranges: DMA 0 -> 4096 Normal 4096 -> 229376 HighMem 229376 -> 524192 Movable zone start PFN for each node early_node_map[1] active PFN ranges 0: 0 -> 524192 On node 0 totalpages: 524192 DMA zone: 32 pages used for memmap DMA zone: 0 pages reserved DMA zone: 4064 pages, LIFO batch:0 Normal zone: 1760 pages used for memmap Normal zone: 223520 pages, LIFO batch:31 HighMem zone: 2303 pages used for memmap HighMem zone: 292513 pages, LIFO batch:31 Movable zone: 0 pages used for memmap DMI 2.3 present. ACPI: RSDP 000FB5E0, 0014 (r0 ACPIAM) ACPI: RSDT 7FFA0000, 003C (r1 A M I OEMRSDT 10000512 MSFT 97) ACPI: FACP 7FFA0200, 0081 (r1 A M I OEMFACP 10000512 MSFT 97) ACPI: DSDT 7FFA0400, 5630 (r1 A0348 A0348000 0 INTL 2002026) ACPI: FACS 7FFB0000, 0040 ACPI: APIC 7FFA0390, 0070 (r1 A M I OEMAPIC 10000512 MSFT 97) ACPI: OEMB 7FFB0040, 0046 (r1 A M I AMI_OEM 10000512 MSFT 97) ACPI: MCFG 7FFA5A30, 003C (r1 A M I OEMMCFG 10000512 MSFT 97) ACPI: SSDT 7FFA5A70, 0137 (r1 AMI CPU1CS 1 INTL 20030522) ACPI: SSDT 7FFA5BB0, 02F0 (r1 AMI CPU1PM 1 INTL 20030522) ACPI: PM-Timer IO Port: 0x808 ACPI: Local APIC address 0xfee00000 ACPI: LAPIC (acpi_id[0x01] lapic_id[0x00] enabled) Processor #0 6:13 APIC version 20 ACPI: LAPIC (acpi_id[0x02] lapic_id[0x81] disabled) ACPI: IOAPIC (id[0x01] address[0xfec00000] gsi_base[0]) IOAPIC[0]: apic_id 1, version 32, address 0xfec00000, GSI 0-23 ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) ACPI: IRQ0 used by override. ACPI: IRQ2 used by override. ACPI: IRQ9 used by override. Enabling APIC mode: Flat. Using 1 I/O APICs Using ACPI (MADT) for SMP configuration information Allocating PCI resources starting at 88000000 (gap: 80000000:7fb80000) PM: Registered nosave memory: 000000000009f000 - 00000000000a0000 PM: Registered nosave memory: 00000000000a0000 - 00000000000e0000 PM: Registered nosave memory: 00000000000e0000 - 0000000000100000 Built 1 zonelists in Zone order, mobility grouping on. Total pages: 520097 Kernel command line: ro root=LABEL=/ crashkernel=64M@16M mapped APIC to ffffb000 (fee00000) mapped IOAPIC to ffffa000 (fec00000) Enabling fast FPU save and restore... done. Enabling unmasked SIMD FPU exception support... done. Initializing CPU#0 CPU 0 irqstacks, hard=c0468000 soft=c0467000 PID hash table entries: 4096 (order: 12, 16384 bytes) Detected 1995.058 MHz processor. Console: colour VGA+ 80x25 console [tty0] enabled Dentry cache hash table entries: 131072 (order: 7, 524288 bytes) Inode-cache hash table entries: 65536 (order: 6, 262144 bytes) Memory: 2006244k/2096768k available (2157k kernel code, 89416k reserved, 1101k data, 208k init, 1179264k highmem) virtual kernel memory layout: fixmap : 0xfffa8000 - 0xfffff000 ( 348 kB) pkmap : 0xff800000 - 0xffc00000 (4096 kB) vmalloc : 0xf8800000 - 0xff7fe000 ( 111 MB) lowmem : 0xc0000000 - 0xf8000000 ( 896 MB) .init : 0xc0430000 - 0xc0464000 ( 208 kB) .data : 0xc031b587 - 0xc042ed20 (1101 kB) .text : 0xc0100000 - 0xc031b587 (2157 kB) Checking if this processor honours the WP bit even in supervisor mode...Ok. CPA: page pool initialized 32 of 32 pages preallocated SLUB: Genslabs=12, HWalign=64, Order=0-1, MinObjects=4, CPUs=1, Nodes=1 Calibrating delay using timer specific routine.. 3991.70 BogoMIPS (lpj=1995853) Security Framework initialized SELinux: Initializing. SELinux: Starting in permissive mode selinux_register_security: Registering secondary module capability Capability LSM initialized as secondary Mount-cache hash table entries: 512 Initializing cgroup subsys ns CPU: L1 I cache: 32K, L1 D cache: 32K CPU: L2 cache: 2048K Intel machine check architecture supported. Intel machine check reporting enabled on CPU#0. Compat vDSO mapped to ffffe000. CPU: Intel(R) Pentium(R) M processor 2.00GHz stepping 08 Checking 'hlt' instruction... OK. Freeing SMP alternatives: 0k freed ACPI: Core revision 20070126 ENABLING IO-APIC IRQs ..TIMER: vector=0x31 apic1=0 pin1=2 apic2=-1 pin2=-1 net_namespace: 444 bytes NET: Registered protocol family 16 ACPI: bus type pci registered PCI: BIOS Bug: MCFG area at e0000000 is not E820-reserved PCI: Not using MMCONFIG. PCI: PCI BIOS revision 2.10 entry at 0xf0031, last bus=4 PCI: Using configuration type 1 Setting up standard PCI resources ACPI: EC: Look up EC in DSDT ACPI: Interpreter enabled ACPI: (supports S0 S1 S3 S4 S5) ACPI: Using IOAPIC for interrupt routing ACPI: EC: non-query interrupt received, switching to interrupt mode ACPI: EC: GPE = 0x1c, I/O: command/status = 0x66, data = 0x62 ACPI: EC: driver started in interrupt mode ACPI: PCI Root Bridge [PCI0] (0000:00) pci 0000:00:1f.0: Enabled ICH6/i801 SMBus device pci 0000:00:1f.0: quirk: region 0800-087f claimed by ICH6 ACPI/GPIO/TCO pci 0000:00:1f.0: quirk: region 0480-04bf claimed by ICH6 GPIO PCI: Transparent bridge - 0000:00:1e.0 ACPI: PCI Interrupt Routing Table [\_SB_.PCI0._PRT] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.P0P1._PRT] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.P0P3._PRT] ACPI: PCI Interrupt Link [LNKA] (IRQs 3 4 5 6 7 *10 11 12 14 15) ACPI: PCI Interrupt Link [LNKB] (IRQs 3 4 5 *6 7 10 11 12 14 15) ACPI: PCI Interrupt Link [LNKC] (IRQs 3 4 *5 6 7 10 11 12 14 15) ACPI: PCI Interrupt Link [LNKD] (IRQs 3 4 5 6 *7 10 11 12 14 15) ACPI: PCI Interrupt Link [LNKE] (IRQs 3 *4 5 6 7 10 11 12 14 15) ACPI: PCI Interrupt Link [LNKF] (IRQs 3 4 5 6 7 10 11 12 14 15) *0, disabled. ACPI: PCI Interrupt Link [LNKG] (IRQs 3 4 5 6 7 10 11 12 14 15) *0, disabled. ACPI: PCI Interrupt Link [LNKH] (IRQs 3 4 5 6 7 10 *11 12 14 15) Linux Plug and Play Support v0.97 (c) Adam Belay pnp: PnP ACPI init ACPI: bus type pnp registered pnp: PnP ACPI: found 17 devices ACPI: ACPI bus type pnp unregistered SCSI subsystem initialized libata version 3.00 loaded. usbcore: registered new interface driver usbfs usbcore: registered new interface driver hub usbcore: registered new device driver usb PCI: Using ACPI for IRQ routing PCI: If a device doesn't work, try "pci=routeirq". If it helps, post a report ACPI: RTC can wake from S4 system 00:01: iomem range 0xfed13000-0xfed19fff has been reserved system 00:09: ioport range 0x6c0-0x6cf has been reserved Time: tsc clocksource has been installed. system 00:0a: ioport range 0x4d0-0x4d1 has been reserved system 00:0a: ioport range 0x800-0x87f has been reserved system 00:0a: ioport range 0x400-0x41f has been reserved system 00:0a: ioport range 0x480-0x4bf has been reserved system 00:0a: iomem range 0xfed1c000-0xfed1ffff has been reserved system 00:0a: iomem range 0xfed20000-0xfed8ffff has been reserved system 00:0c: iomem range 0xffc00000-0xfff7ffff could not be reserved system 00:0d: iomem range 0xfec00000-0xfec00fff has been reserved system 00:0d: iomem range 0xfee00000-0xfee00fff has been reserved system 00:0e: iomem range 0xe0000000-0xefffffff has been reserved system 00:0f: iomem range 0xe0000000-0xefffffff has been reserved system 00:10: iomem range 0x0-0x9ffff could not be reserved system 00:10: iomem range 0xc0000-0xcffff could not be reserved system 00:10: iomem range 0xe0000-0xfffff could not be reserved system 00:10: iomem range 0x100000-0x7fffffff could not be reserved system 00:10: iomem range 0x0-0x0 could not be reserved PCI: Bridge: 0000:00:01.0 IO window: b000-bfff MEM window: 0xfbe00000-0xfbefffff PREFETCH window: 0x00000000f0000000-0x00000000faffffff PCI: Bridge: 0000:00:1c.0 IO window: c000-cfff MEM window: disabled. PREFETCH window: disabled. PCI: Bus 4, cardbus bridge: 0000:03:01.0 IO window: 0x0000d000-0x0000d0ff IO window: 0x0000d400-0x0000d4ff PREFETCH window: 0x88000000-0x8bffffff MEM window: 0x8c000000-0x8fffffff PCI: Bridge: 0000:00:1e.0 IO window: d000-efff MEM window: 0xfbf00000-0xfbffffff PREFETCH window: disabled. ACPI: PCI Interrupt 0000:00:01.0[A] -> GSI 16 (level, low) -> IRQ 16 PCI: Setting latency timer of device 0000:00:01.0 to 64 ACPI: PCI Interrupt 0000:00:1c.0[A] -> GSI 16 (level, low) -> IRQ 16 PCI: Setting latency timer of device 0000:00:1c.0 to 64 PCI: Setting latency timer of device 0000:00:1e.0 to 64 ACPI: PCI Interrupt 0000:03:01.0[A] -> GSI 17 (level, low) -> IRQ 17 NET: Registered protocol family 2 IP route cache hash table entries: 32768 (order: 5, 131072 bytes) TCP established hash table entries: 131072 (order: 8, 1048576 bytes) TCP bind hash table entries: 65536 (order: 6, 262144 bytes) TCP: Hash tables configured (established 131072 bind 65536) TCP reno registered checking if image is initramfs... it is Freeing initrd memory: 2750k freed Machine check exception polling timer started. apm: BIOS version 1.2 Flags 0x03 (Driver version 1.16ac) apm: overridden by ACPI. audit: initializing netlink socket (disabled) type=2000 audit(1203759070.431:1): initialized Kprobe smoke test started Kprobe smoke test passed successfully highmem bounce pool size: 64 pages Total HugeTLB memory allocated, 0 VFS: Disk quotas dquot_6.5.1 Dquot-cache hash table entries: 1024 (order 0, 4096 bytes) SELinux: Registering netfilter hooks Block layer SCSI generic (bsg) driver version 0.4 loaded (major 254) io scheduler noop registered io scheduler cfq registered (default) pci 0000:01:00.0: Boot video device PCI: Setting latency timer of device 0000:00:01.0 to 64 assign_interrupt_mode Found MSI capability Allocate Port Service[0000:00:01.0:pcie00] PCI: Setting latency timer of device 0000:00:1c.0 to 64 assign_interrupt_mode Found MSI capability Allocate Port Service[0000:00:1c.0:pcie00] Allocate Port Service[0000:00:1c.0:pcie02] ACPI: CPU0 (power states: C1[C1] C2[C2] C3[C3]) ACPI: ACPI0007:00 is registered as cooling_device0 ACPI: Processor [CPU1] (supports 8 throttling states) ACPI: LNXTHERM:01 is registered as thermal_zone0 ACPI: Thermal Zone [TZ00] (43 C) Real Time Clock Driver v1.12ac Non-volatile memory driver v1.2 Linux agpgart interface v0.103 Serial: 8250/16550 driver $Revision: 1.90 $ 4 ports, IRQ sharing enabled serial8250: ttyS1 at I/O 0x2f8 (irq = 3) is a 16550A ACPI: PCI Interrupt 0000:00:1e.3[B] -> GSI 20 (level, low) -> IRQ 20 ACPI: PCI interrupt for device 0000:00:1e.3 disabled brd: module loaded Driver 'sd' needs updating - please use bus_type methods ata_piix 0000:00:1f.1: version 2.12 ACPI: PCI Interrupt 0000:00:1f.1[A] -> GSI 18 (level, low) -> IRQ 18 PCI: Setting latency timer of device 0000:00:1f.1 to 64 scsi0 : ata_piix scsi1 : ata_piix ata1: PATA max UDMA/100 cmd 0x1f0 ctl 0x3f6 bmdma 0xffa0 irq 14 ata2: PATA max UDMA/100 cmd 0x170 ctl 0x376 bmdma 0xffa8 irq 15 Switched to high resolution mode on CPU 0 ata1.00: ATA-6: HTS541010G9AT00, MBZOA60A, max UDMA/100 ata1.00: 195371568 sectors, multi 16: LBA48 ata1.01: ATAPI: MATSHITADVD-RAM UJ-832S, 1.00, max UDMA/33 ata1.00: configured for UDMA/100 ata1.01: configured for UDMA/33 ata2: port disabled. ignoring. scsi 0:0:0:0: Direct-Access ATA HTS541010G9AT00 MBZO PQ: 0 ANSI: 5 sd 0:0:0:0: [sda] 195371568 512-byte hardware sectors (100030 MB) sd 0:0:0:0: [sda] Write Protect is off sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00 sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA sd 0:0:0:0: [sda] 195371568 512-byte hardware sectors (100030 MB) sd 0:0:0:0: [sda] Write Protect is off sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00 sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA sda: sda1 sda2 sd 0:0:0:0: [sda] Attached SCSI disk scsi 0:0:1:0: CD-ROM MATSHITA DVD-RAM UJ-832S 1.00 PQ: 0 ANSI: 5 Yenta: CardBus bridge found at 0000:03:01.0 [1043:1967] Yenta: ISA IRQ mask 0x0cb8, PCI irq 17 Socket status: 30000006 Yenta: Raising subordinate bus# of parent bus (#03) from #04 to #07 pcmcia: parent PCI bridge I/O window: 0xd000 - 0xefff cs: IO port probe 0xd000-0xefff: clean. pcmcia: parent PCI bridge Memory window: 0xfbf00000 - 0xfbffffff PNP: PS/2 Controller [PNP0303:PS2K,PNP0f13:PS2M] at 0x60,0x64 irq 1,12 i8042.c: Detected active multiplexing controller, rev 1.1. serio: i8042 KBD port at 0x60,0x64 irq 1 serio: i8042 AUX0 port at 0x60,0x64 irq 12 serio: i8042 AUX1 port at 0x60,0x64 irq 12 serio: i8042 AUX2 port at 0x60,0x64 irq 12 serio: i8042 AUX3 port at 0x60,0x64 irq 12 mice: PS/2 mouse device common for all mice cpuidle: using governor ladder Synaptics Touchpad, model: 1, fw: 5.9, id: 0x256eb1, caps: 0x804713/0x0 input: SynPS/2 Synaptics TouchPad as /class/input/input0 input: AT Translated Set 2 keyboard as /class/input/input1 cpuidle: using governor menu TCP cubic registered Initializing XFRM netlink socket NET: Registered protocol family 1 NET: Registered protocol family 17 Using IPI Shortcut mode registered taskstats version 1 Freeing unused kernel memory: 208k freed Marking TSC unstable due to: TSC halts in idle. Time: acpi_pm clocksource has been installed. ACPI: PCI Interrupt 0000:00:1d.7[A] -> GSI 23 (level, low) -> IRQ 23 PCI: Setting latency timer of device 0000:00:1d.7 to 64 ehci_hcd 0000:00:1d.7: EHCI Host Controller ehci_hcd 0000:00:1d.7: new USB bus registered, assigned bus number 1 ehci_hcd 0000:00:1d.7: debug port 1 PCI: cache line size of 32 is not supported by device 0000:00:1d.7 ehci_hcd 0000:00:1d.7: irq 23, io mem 0xfbdffc00 ehci_hcd 0000:00:1d.7: USB 2.0 started, EHCI 1.00, driver 10 Dec 2004 usb usb1: configuration #1 chosen from 1 choice hub 1-0:1.0: USB hub found hub 1-0:1.0: 8 ports detected usb usb1: New USB device found, idVendor=1d6b, idProduct=0002 usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1 usb usb1: Product: EHCI Host Controller usb usb1: Manufacturer: Linux 2.6.25-rc2-gc-00243-g54a8145 ehci_hcd usb usb1: SerialNumber: 0000:00:1d.7 ohci_hcd: 2006 August 04 USB 1.1 'Open' Host Controller (OHCI) Driver USB Universal Host Controller Interface driver v3.0 ACPI: PCI Interrupt 0000:00:1d.0[A] -> GSI 23 (level, low) -> IRQ 23 PCI: Setting latency timer of device 0000:00:1d.0 to 64 uhci_hcd 0000:00:1d.0: UHCI Host Controller uhci_hcd 0000:00:1d.0: new USB bus registered, assigned bus number 2 uhci_hcd 0000:00:1d.0: irq 23, io base 0x00009800 usb usb2: configuration #1 chosen from 1 choice hub 2-0:1.0: USB hub found hub 2-0:1.0: 2 ports detected usb usb2: New USB device found, idVendor=1d6b, idProduct=0001 usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1 usb usb2: Product: UHCI Host Controller usb usb2: Manufacturer: Linux 2.6.25-rc2-gc-00243-g54a8145 uhci_hcd usb usb2: SerialNumber: 0000:00:1d.0 ACPI: PCI Interrupt 0000:00:1d.1[B] -> GSI 19 (level, low) -> IRQ 19 PCI: Setting latency timer of device 0000:00:1d.1 to 64 uhci_hcd 0000:00:1d.1: UHCI Host Controller uhci_hcd 0000:00:1d.1: new USB bus registered, assigned bus number 3 uhci_hcd 0000:00:1d.1: irq 19, io base 0x0000a000 usb usb3: configuration #1 chosen from 1 choice hub 3-0:1.0: USB hub found hub 3-0:1.0: 2 ports detected usb usb3: New USB device found, idVendor=1d6b, idProduct=0001 usb usb3: New USB device strings: Mfr=3, Product=2, SerialNumber=1 usb usb3: Product: UHCI Host Controller usb usb3: Manufacturer: Linux 2.6.25-rc2-gc-00243-g54a8145 uhci_hcd usb usb3: SerialNumber: 0000:00:1d.1 ACPI: PCI Interrupt 0000:00:1d.2[C] -> GSI 18 (level, low) -> IRQ 18 PCI: Setting latency timer of device 0000:00:1d.2 to 64 uhci_hcd 0000:00:1d.2: UHCI Host Controller uhci_hcd 0000:00:1d.2: new USB bus registered, assigned bus number 4 uhci_hcd 0000:00:1d.2: irq 18, io base 0x0000a400 usb usb4: configuration #1 chosen from 1 choice hub 4-0:1.0: USB hub found hub 4-0:1.0: 2 ports detected usb usb4: New USB device found, idVendor=1d6b, idProduct=0001 usb usb4: New USB device strings: Mfr=3, Product=2, SerialNumber=1 usb usb4: Product: UHCI Host Controller usb usb4: Manufacturer: Linux 2.6.25-rc2-gc-00243-g54a8145 uhci_hcd usb usb4: SerialNumber: 0000:00:1d.2 ACPI: PCI Interrupt 0000:00:1d.3[D] -> GSI 16 (level, low) -> IRQ 16 PCI: Setting latency timer of device 0000:00:1d.3 to 64 uhci_hcd 0000:00:1d.3: UHCI Host Controller uhci_hcd 0000:00:1d.3: new USB bus registered, assigned bus number 5 uhci_hcd 0000:00:1d.3: irq 16, io base 0x0000a800 usb usb5: configuration #1 chosen from 1 choice hub 5-0:1.0: USB hub found hub 5-0:1.0: 2 ports detected usb 2-2: new low speed USB device using uhci_hcd and address 2 usb usb5: New USB device found, idVendor=1d6b, idProduct=0001 usb usb5: New USB device strings: Mfr=3, Product=2, SerialNumber=1 usb usb5: Product: UHCI Host Controller usb usb5: Manufacturer: Linux 2.6.25-rc2-gc-00243-g54a8145 uhci_hcd usb usb5: SerialNumber: 0000:00:1d.3 usb 2-2: configuration #1 chosen from 1 choice usb 2-2: New USB device found, idVendor=046d, idProduct=c016 usb 2-2: New USB device strings: Mfr=1, Product=2, SerialNumber=0 usb 2-2: Product: Optical USB Mouse usb 2-2: Manufacturer: Logitech kjournald starting. Commit interval 5 seconds EXT3-fs: mounted filesystem with ordered data mode. SELinux: Disabled at runtime. SELinux: Unregistering netfilter hooks type=1404 audit(1203759077.068:2): selinux=0 auid=4294967295 ses=4294967295 Driver 'sr' needs updating - please use bus_type methods sr0: scsi3-mmc drive: 24x/24x writer dvd-ram cd/rw xa/form2 cdda tray Uniform CD-ROM driver Revision: 3.20 sr 0:0:1:0: Attached scsi CD-ROM sr0 sdhci: Secure Digital Host Controller Interface driver sdhci: Copyright(c) Pierre Ossman sdhci: SDHCI controller found at 0000:03:01.2 [1180:0822] (rev 17) ACPI: PCI Interrupt 0000:03:01.2[C] -> GSI 18 (level, low) -> IRQ 18 sdhc0:slot0: Will use DMA mode even though HW doesn't fully claim to support it. mmc0: SDHCI at 0xfbffb400 irq 18 DMA ieee80211_crypt: registered algorithm 'NULL' cs: IO port probe 0x100-0x3af: clean. cs: IO port probe 0x3e0-0x4ff: clean. cs: IO port probe 0x820-0x8ff: clean. cs: IO port probe 0xc00-0xcf7: clean. cs: IO port probe 0xa00-0xaff: clean. input: PC Speaker as /class/input/input2 ACPI: PCI Interrupt 0000:03:00.0[A] -> GSI 18 (level, low) -> IRQ 18 skge 1.13 addr 0xfbffc000 irq 18 chip Yukon-Lite rev 9 skge eth0: addr 00:15:f2:46:d3:3b ACPI: Battery Slot [BAT0] (battery present) NET: Registered protocol family 23 asus-laptop: Asus Laptop Support version 0.42 asus-laptop: Error calling BSTS asus-laptop: V6VA model detected Registered led device: asus::touchpad ACPI: AC Adapter [AC0] (on-line) input: Power Button (FF) as /class/input/input3 ACPI: Power Button (FF) [PWRF] input: Sleep Button (CM) as /class/input/input4 ACPI: Sleep Button (CM) [SLPB] input: Lid Switch as /class/input/input5 ACPI: Lid Switch [LID] input: Power Button (CM) as /class/input/input6 ACPI: Power Button (CM) [PWRB] iTCO_wdt: Intel TCO WatchDog Timer Driver v1.02 (26-Jul-2007) iTCO_wdt: Found a ICH6-M TCO device (Version=2, TCOBASE=0x0860) iTCO_wdt: initialized. heartbeat=30 sec (nowayout=0) usb 5-1: new full speed USB device using uhci_hcd and address 2 intel_rng: FWH not detected ACPI: PCI Interrupt 0000:00:1f.3[B] -> GSI 19 (level, low) -> IRQ 19 rtc_cmos: probe of 00:03 failed with error -16 sd 0:0:0:0: Attached scsi generic sg0 type 0 sr 0:0:1:0: Attached scsi generic sg1 type 5 usb 5-1: configuration #1 chosen from 1 choice usb 5-1: New USB device found, idVendor=044e, idProduct=3001 usb 5-1: New USB device strings: Mfr=1, Product=2, SerialNumber=0 usb 5-1: Product: UGPZ usb 5-1: Manufacturer: ALPS ACPI: PCI Interrupt 0000:03:01.1[B] -> GSI 16 (level, low) -> IRQ 16 ieee80211: 802.11 data/management/control stack, git-1.1.13 ieee80211: Copyright (C) 2004-2005 Intel Corporation <jketreno@linux.intel.com> usbcore: registered new interface driver hiddev firewire_ohci: Added fw-ohci device 0000:03:01.1, OHCI version 1.0 input: Logitech Optical USB Mouse as /class/input/input7 input,hidraw0: USB HID v1.10 Mouse [Logitech Optical USB Mouse] on usb-0000:00:1d.0-2 usbcore: registered new interface driver usbhid /home/g/linux-2.6/drivers/hid/usbhid/hid-core.c: v2.6:USB HID core driver Bluetooth: Core ver 2.11 NET: Registered protocol family 31 Bluetooth: HCI device and connection manager initialized Bluetooth: HCI socket layer initialized firewire_core: created new fw device fw0 (0 config rom retries, S400) ipw2200: Intel(R) PRO/Wireless 2200/2915 Network Driver, 1.2.2kmprq ipw2200: Copyright(c) 2003-2006 Intel Corporation ACPI: PCI Interrupt 0000:03:02.0[A] -> GSI 17 (level, low) -> IRQ 17 Bluetooth: HCI USB driver ver 2.9 usbcore: registered new interface driver hci_usb ipw2200: Detected Intel PRO/Wireless 2200BG Network Connection ipw2200: Detected geography ZZM (11 802.11bg channels, 0 802.11a channels) ACPI: PCI Interrupt 0000:00:1e.2[A] -> GSI 17 (level, low) -> IRQ 17 PCI: Setting latency timer of device 0000:00:1e.2 to 64 Clocksource tsc unstable (delta = -84108096 ns) intel8x0_measure_ac97_clock: measured 50462 usecs intel8x0: clocking to 48000 ACPI: PCI Interrupt 0000:00:1e.3[B] -> GSI 20 (level, low) -> IRQ 20 PCI: Setting latency timer of device 0000:00:1e.3 to 64 ALSA /home/g/linux-2.6/sound/pci/ac97/ac97_codec.c:2152: MC'97 1 converters and GPIO not ready (0xff00) device-mapper: uevent: version 1.0.3 device-mapper: ioctl: 4.13.0-ioctl (2007-10-18) initialised: dm-devel@redhat.com EXT3 FS on sda1, internal journal Adding 3478064k swap on /dev/sda2. Priority:-1 extents:1 across:3478064k warning: `dbus-daemon' uses 32-bit capabilities (legacy support in use) skge eth0: enabling interface ACPI: PCI Interrupt 0000:01:00.0[A] -> GSI 16 (level, low) -> IRQ 16 [drm] Initialized drm 1.1.0 20060810 PCI: Setting latency timer of device 0000:01:00.0 to 64 [drm] Initialized radeon 1.28.0 20060524 on minor 0 [drm] Setting GART location based on new memory map [drm] Loading R300 Microcode [drm] writeback test succeeded in 1 usecs ipw2200: Failed to send SYSTEM_CONFIG: Already sending a command. usb 2-2: USB disconnect, address 2 ipw2200: Failed to send SYSTEM_CONFIG: Command timed out. usb 2-2: new low speed USB device using uhci_hcd and address 3 usb 2-2: configuration #1 chosen from 1 choice input: Logitech Optical USB Mouse as /class/input/input8 input,hidraw0: USB HID v1.10 Mouse [Logitech Optical USB Mouse] on usb-0000:00:1d.0-2 usb 2-2: New USB device found, idVendor=046d, idProduct=c016 usb 2-2: New USB device strings: Mfr=1, Product=2, SerialNumber=0 usb 2-2: Product: Optical USB Mouse usb 2-2: Manufacturer: Logitech ipw2200: Failed to send SYSTEM_CONFIG: Command timed out. usb 2-2: USB disconnect, address 3 KERNEL: assertion (packets <= tp->packets_out) failed at /home/g/linux-2.6/net/ipv4/tcp_input.c (2145) KERNEL: assertion (packets <= tp->packets_out) failed at /home/g/linux-2.6/net/ipv4/tcp_input.c (2145) ------------[ cut here ]------------ WARNING: at /home/g/linux-2.6/net/ipv4/tcp_input.c:2515 tcp_fastretrans_alert+0xa5/0xa4f() Modules linked in: radeon drm acpi_cpufreq lm90 hwmon binfmt_misc dm_mirror dm_mod snd_intel8x0m snd_intel8x0 snd_seq_dummy snd_ac97_codec ac97_bus snd_seq_oss snd_seq_midi_event snd_seq snd_seq_device snd_pcm_oss snd_mixer_oss snd_pcm snd_timer snd ohci1394 ieee1394 hci_usb ipw2200 bluetooth usbhid ieee80211 firewire_ohci soundcore hid snd_page_alloc sg rtc_cmos i2c_i801 iTCO_wdt serio_raw firewire_core button ac asus_laptop i2c_core rtc_core crc_itu_t irda crc_ccitt battery skge led_class rtc_lib pcspkr ieee80211_crypt sdhci mmc_core sr_mod cdrom pata_acpi uhci_hcd ohci_hcd ehci_hcd Pid: 0, comm: swapper Not tainted 2.6.25-rc2-gc-00243-g54a8145 #379 [<c011aff0>] warn_on_slowpath+0x41/0x51 [<c02e0ae0>] ? tcp_sacktag_walk+0x67/0x2a6 [<c02e9c9f>] ? tcp_v4_send_check+0x77/0xb1 [<c02e5aa2>] ? tcp_transmit_skb+0x644/0x677 [<c0169634>] ? __slab_free+0x56/0x262 [<c02b5738>] ? skb_release_data+0x84/0x89 [<c016a004>] ? kfree+0x6e/0x7a [<c02b5738>] ? skb_release_data+0x84/0x89 [<c02e0046>] tcp_fastretrans_alert+0xa5/0xa4f [<c02e2089>] tcp_ack+0xba6/0xcf9 [<c02e4740>] tcp_rcv_established+0xdb/0x5fb [<c02e960e>] tcp_v4_do_rcv+0x28/0x188 [<c02ead20>] tcp_v4_rcv+0x5a2/0x607 [<f8985daf>] ? ipw_rx+0x12b5/0x12bd [ipw2200] [<c02d4165>] ip_local_deliver_finish+0xda/0x16a [<c02d4543>] ip_local_deliver+0x64/0x6d [<c02d406c>] ip_rcv_finish+0x244/0x263 [<c02d44c1>] ip_rcv+0x1d2/0x1f0 [<c02b9e86>] netif_receive_skb+0x34d/0x3d1 [<c02bbc2f>] process_backlog+0x5b/0xa5 [<c02bb849>] net_rx_action+0x86/0x166 [<c011f418>] __do_softirq+0x38/0x7a [<c0106327>] do_softirq+0x3e/0x72 [<c014a0e3>] ? handle_fasteoi_irq+0x0/0xbd [<c011f364>] irq_exit+0x28/0x61 [<c01063f0>] do_IRQ+0x95/0xaa [<c0105293>] common_interrupt+0x23/0x28 [<c014007b>] ? cgroup_scan_tasks+0x73/0x15b [<c0110000>] ? io_apic_set_pci_routing+0x2b/0x119 [<c023a59c>] ? acpi_idle_enter_simple+0x15b/0x1c7 [<c023a6bb>] acpi_idle_enter_bm+0xb3/0x2cc [<c02acc2b>] cpuidle_idle_call+0x4c/0x71 [<c02acbdf>] ? cpuidle_idle_call+0x0/0x71 [<c0103570>] cpu_idle+0x5a/0x87 [<c0311af8>] rest_init+0x5c/0x5e ======================= ---[ end trace c3302487bda6288d ]--- usb 2-2: new low speed USB device using uhci_hcd and address 4 usb 2-2: configuration #1 chosen from 1 choice input: Logitech Optical USB Mouse as /class/input/input9 input,hidraw0: USB HID v1.10 Mouse [Logitech Optical USB Mouse] on usb-0000:00:1d.0-2 usb 2-2: New USB device found, idVendor=046d, idProduct=c016 usb 2-2: New USB device strings: Mfr=1, Product=2, SerialNumber=0 usb 2-2: Product: Optical USB Mouse usb 2-2: Manufacturer: Logitech ipw2200: Firmware error detected. Restarting. ------------[ cut here ]------------ WARNING: at /home/g/linux-2.6/net/ipv4/tcp_input.c:2515 tcp_fastretrans_alert+0xa5/0xa4f() Modules linked in: radeon drm acpi_cpufreq lm90 hwmon binfmt_misc dm_mirror dm_mod snd_intel8x0m snd_intel8x0 snd_seq_dummy snd_ac97_codec ac97_bus snd_seq_oss snd_seq_midi_event snd_seq snd_seq_device snd_pcm_oss snd_mixer_oss snd_pcm snd_timer snd ohci1394 ieee1394 hci_usb ipw2200 bluetooth usbhid ieee80211 firewire_ohci soundcore hid snd_page_alloc sg rtc_cmos i2c_i801 iTCO_wdt serio_raw firewire_core button ac asus_laptop i2c_core rtc_core crc_itu_t irda crc_ccitt battery skge led_class rtc_lib pcspkr ieee80211_crypt sdhci mmc_core sr_mod cdrom pata_acpi uhci_hcd ohci_hcd ehci_hcd Pid: 0, comm: swapper Not tainted 2.6.25-rc2-gc-00243-g54a8145 #379 [<c011aff0>] warn_on_slowpath+0x41/0x51 [<c02c0066>] ? neigh_seq_start+0x2e/0xa0 [<c02bc8f1>] ? dev_queue_xmit+0x296/0x2bd [<c02e9c9f>] ? tcp_v4_send_check+0x77/0xb1 [<c02bc8f1>] ? dev_queue_xmit+0x296/0x2bd [<c02d7709>] ? ip_finish_output+0x1dd/0x218 [<c0115044>] ? __enqueue_entity+0x9c/0xa4 [<c02b5738>] ? skb_release_data+0x84/0x89 [<c016a004>] ? kfree+0x6e/0x7a [<c02b5738>] ? skb_release_data+0x84/0x89 [<c02e0046>] tcp_fastretrans_alert+0xa5/0xa4f [<c02e2089>] tcp_ack+0xba6/0xcf9 [<c02e4b8e>] tcp_rcv_established+0x529/0x5fb [<c011522a>] ? hrtick_start_fair+0xce/0x10a [<c02e960e>] tcp_v4_do_rcv+0x28/0x188 [<c02ead20>] tcp_v4_rcv+0x5a2/0x607 [<f8985daf>] ? ipw_rx+0x12b5/0x12bd [ipw2200] [<c02d4165>] ip_local_deliver_finish+0xda/0x16a [<c02d4543>] ip_local_deliver+0x64/0x6d [<c02d406c>] ip_rcv_finish+0x244/0x263 [<c02d44c1>] ip_rcv+0x1d2/0x1f0 [<c02b9e86>] netif_receive_skb+0x34d/0x3d1 [<c02bbc2f>] process_backlog+0x5b/0xa5 [<c02bb849>] net_rx_action+0x86/0x166 [<c011f418>] __do_softirq+0x38/0x7a [<c0106327>] do_softirq+0x3e/0x72 [<c014a0e3>] ? handle_fasteoi_irq+0x0/0xbd [<c011f364>] irq_exit+0x28/0x61 [<c01063f0>] do_IRQ+0x95/0xaa [<c0105293>] common_interrupt+0x23/0x28 [<c014007b>] ? cgroup_scan_tasks+0x73/0x15b [<c0110000>] ? io_apic_set_pci_routing+0x2b/0x119 [<c023a59c>] ? acpi_idle_enter_simple+0x15b/0x1c7 [<c023a6bb>] acpi_idle_enter_bm+0xb3/0x2cc [<c02acc2b>] cpuidle_idle_call+0x4c/0x71 [<c02acbdf>] ? cpuidle_idle_call+0x0/0x71 [<c0103570>] cpu_idle+0x5a/0x87 [<c0311af8>] rest_init+0x5c/0x5e ======================= ---[ end trace c3302487bda6288d ]--- usb 1-4: new high speed USB device using ehci_hcd and address 6 usb 1-4: configuration #1 chosen from 1 choice usb 1-4: New USB device found, idVendor=1058, idProduct=0910 usb 1-4: New USB device strings: Mfr=1, Product=2, SerialNumber=3 usb 1-4: Product: External HDD usb 1-4: Manufacturer: Western Digital usb 1-4: SerialNumber: 574341533830323934323231 Initializing USB Mass Storage driver... scsi2 : SCSI emulation for USB Mass Storage devices usbcore: registered new interface driver usb-storage USB Mass Storage support registered. usb-storage: device found at 6 usb-storage: waiting for device to settle before scanning scsi 2:0:0:0: Direct-Access WD 5000AAK External 1.06 PQ: 0 ANSI: 0 sd 2:0:0:0: [sdb] 976773168 512-byte hardware sectors (500108 MB) sd 2:0:0:0: [sdb] Write Protect is off sd 2:0:0:0: [sdb] Mode Sense: 00 00 00 00 sd 2:0:0:0: [sdb] Assuming drive cache: write through sd 2:0:0:0: [sdb] 976773168 512-byte hardware sectors (500108 MB) sd 2:0:0:0: [sdb] Write Protect is off sd 2:0:0:0: [sdb] Mode Sense: 00 00 00 00 sd 2:0:0:0: [sdb] Assuming drive cache: write through sdb: sdb1 sdb2 sdb3 sdb4 sd 2:0:0:0: [sdb] Attached SCSI disk sd 2:0:0:0: Attached scsi generic sg2 type 0 usb-storage: device scan complete kjournald starting. Commit interval 5 seconds EXT3-fs warning: maximal mount count reached, running e2fsck is recommended EXT3 FS on sdb4, internal journal EXT3-fs: mounted filesystem with ordered data mode. kjournald starting. Commit interval 5 seconds EXT3 FS on sdb2, internal journal EXT3-fs: mounted filesystem with ordered data mode. EXT3-fs warning: maximal mount count reached, running e2fsck is recommended kjournald starting. Commit interval 5 seconds EXT3 FS on sdb1, internal journal EXT3-fs: mounted filesystem with ordered data mode. EXT3-fs warning: maximal mount count reached, running e2fsck is recommended kjournald starting. Commit interval 5 seconds EXT3 FS on sdb3, internal journal EXT3-fs: mounted filesystem with ordered data mode. usb 1-4: USB disconnect, address 6 usb 1-4: new high speed USB device using ehci_hcd and address 7 usb 1-4: configuration #1 chosen from 1 choice scsi3 : SCSI emulation for USB Mass Storage devices usb 1-4: New USB device found, idVendor=1058, idProduct=0910 usb 1-4: New USB device strings: Mfr=1, Product=2, SerialNumber=3 usb 1-4: Product: External HDD usb 1-4: Manufacturer: Western Digital usb 1-4: SerialNumber: 574341533830323934323231 usb-storage: device found at 7 usb-storage: waiting for device to settle before scanning scsi 3:0:0:0: Direct-Access WD 5000AAK External 1.06 PQ: 0 ANSI: 0 sd 3:0:0:0: [sdb] 976773168 512-byte hardware sectors (500108 MB) sd 3:0:0:0: [sdb] Write Protect is off sd 3:0:0:0: [sdb] Mode Sense: 00 00 00 00 sd 3:0:0:0: [sdb] Assuming drive cache: write through sd 3:0:0:0: [sdb] 976773168 512-byte hardware sectors (500108 MB) sd 3:0:0:0: [sdb] Write Protect is off sd 3:0:0:0: [sdb] Mode Sense: 00 00 00 00 sd 3:0:0:0: [sdb] Assuming drive cache: write through sdb: sdb1 sdb2 sdb3 sdb4 sd 3:0:0:0: [sdb] Attached SCSI disk sd 3:0:0:0: Attached scsi generic sg2 type 0 usb-storage: device scan complete kjournald starting. Commit interval 5 seconds EXT3 FS on sdb2, internal journal EXT3-fs: mounted filesystem with ordered data mode. EXT3-fs warning: maximal mount count reached, running e2fsck is recommended kjournald starting. Commit interval 5 seconds EXT3 FS on sdb4, internal journal EXT3-fs: mounted filesystem with ordered data mode. EXT3-fs warning: maximal mount count reached, running e2fsck is recommended kjournald starting. Commit interval 5 seconds EXT3 FS on sdb1, internal journal EXT3-fs: mounted filesystem with ordered data mode. kjournald starting. Commit interval 5 seconds EXT3-fs warning: maximal mount count reached, running e2fsck is recommended EXT3 FS on sdb3, internal journal EXT3-fs: mounted filesystem with ordered data mode. usb 1-3: new high speed USB device using ehci_hcd and address 8 usb 1-3: configuration #1 chosen from 1 choice scsi4 : SCSI emulation for USB Mass Storage devices usb 1-3: New USB device found, idVendor=067b, idProduct=2507 usb 1-3: New USB device strings: Mfr=1, Product=2, SerialNumber=3 usb 1-3: Product: Mass Storage Device usb 1-3: Manufacturer: Prolific Technology Inc. usb 1-3: SerialNumber: 0 usb-storage: device found at 8 usb-storage: waiting for device to settle before scanning scsi 4:0:0:0: Direct-Access SAMSUNG HD300LD WK10 PQ: 0 ANSI: 0 sd 4:0:0:0: [sdc] 586072367 512-byte hardware sectors (300069 MB) sd 4:0:0:0: [sdc] Write Protect is off sd 4:0:0:0: [sdc] Mode Sense: 03 00 00 00 sd 4:0:0:0: [sdc] Assuming drive cache: write through sd 4:0:0:0: [sdc] 586072367 512-byte hardware sectors (300069 MB) sd 4:0:0:0: [sdc] Write Protect is off sd 4:0:0:0: [sdc] Mode Sense: 03 00 00 00 sd 4:0:0:0: [sdc] Assuming drive cache: write through sdc: sdc1 sdc2 sdc3 sdc4 sd 4:0:0:0: [sdc] Attached SCSI disk sd 4:0:0:0: Attached scsi generic sg3 type 0 usb-storage: device scan complete kjournald starting. Commit interval 5 seconds EXT3-fs warning: maximal mount count reached, running e2fsck is recommended EXT3 FS on sdc1, internal journal EXT3-fs: mounted filesystem with ordered data mode. EXT3-fs warning: maximal mount count reached, running e2fsck is recommended kjournald starting. Commit interval 5 seconds EXT3 FS on sdc2, internal journal EXT3-fs: mounted filesystem with ordered data mode. EXT3-fs warning: maximal mount count reached, running e2fsck is recommended kjournald starting. Commit interval 5 seconds EXT3 FS on sdc4, internal journal EXT3-fs: mounted filesystem with ordered data mode. EXT3-fs warning: maximal mount count reached, running e2fsck is recommended kjournald starting. Commit interval 5 seconds EXT3 FS on sdc3, internal journal EXT3-fs: mounted filesystem with ordered data mode. usb 1-3: USB disconnect, address 8 usb 1-4: USB disconnect, address 7 ipw2200: Failed to send SYSTEM_CONFIG: Command timed out. ipw2200: Failed to send SSID: Command timed out. ipw2200: Failed to send SSID: Command timed out. ipw2200: Firmware error detected. Restarting. ipw2200: Firmware error detected. Restarting. ipw2200: Failed to send SYSTEM_CONFIG: Command timed out. ipw2200: Firmware error detected. Restarting. ipw2200: Failed to send SYSTEM_CONFIG: Command timed out. KERNEL: assertion (packets <= tp->packets_out) failed at /home/g/linux-2.6/net/ipv4/tcp_input.c (2145) KERNEL: assertion (packets <= tp->packets_out) failed at /home/g/linux-2.6/net/ipv4/tcp_input.c (2145) KERNEL: assertion (packets <= tp->packets_out) failed at /home/g/linux-2.6/net/ipv4/tcp_input.c (2145) KERNEL: assertion (packets <= tp->packets_out) failed at /home/g/linux-2.6/net/ipv4/tcp_input.c (2145) KERNEL: assertion (packets <= tp->packets_out) failed at /home/g/linux-2.6/net/ipv4/tcp_input.c (2145) KERNEL: assertion (packets <= tp->packets_out) failed at /home/g/linux-2.6/net/ipv4/tcp_input.c (2145) KERNEL: assertion (packets <= tp->packets_out) failed at /home/g/linux-2.6/net/ipv4/tcp_input.c (2145) KERNEL: assertion (packets <= tp->packets_out) failed at /home/g/linux-2.6/net/ipv4/tcp_input.c (2145) KERNEL: assertion (packets <= tp->packets_out) failed at /home/g/linux-2.6/net/ipv4/tcp_input.c (2145) KERNEL: assertion (packets <= tp->packets_out) failed at /home/g/linux-2.6/net/ipv4/tcp_input.c (2145) KERNEL: assertion (packets <= tp->packets_out) failed at /home/g/linux-2.6/net/ipv4/tcp_input.c (2145) KERNEL: assertion (packets <= tp->packets_out) failed at /home/g/linux-2.6/net/ipv4/tcp_input.c (2145) KERNEL: assertion (packets <= tp->packets_out) failed at /home/g/linux-2.6/net/ipv4/tcp_input.c (2145) KERNEL: assertion (packets <= tp->packets_out) failed at /home/g/linux-2.6/net/ipv4/tcp_input.c (2145) ------------[ cut here ]------------ WARNING: at /home/g/linux-2.6/net/ipv4/tcp_input.c:2515 tcp_fastretrans_alert+0xa5/0xa4f() Modules linked in: usb_storage radeon drm acpi_cpufreq lm90 hwmon binfmt_misc dm_mirror dm_mod snd_intel8x0m snd_intel8x0 snd_seq_dummy snd_ac97_codec ac97_bus snd_seq_oss snd_seq_midi_event snd_seq snd_seq_device snd_pcm_oss snd_mixer_oss snd_pcm snd_timer snd ohci1394 ieee1394 hci_usb ipw2200 bluetooth usbhid ieee80211 firewire_ohci soundcore hid snd_page_alloc sg rtc_cmos i2c_i801 iTCO_wdt serio_raw firewire_core button ac asus_laptop i2c_core rtc_core crc_itu_t irda crc_ccitt battery skge led_class rtc_lib pcspkr ieee80211_crypt sdhci mmc_core sr_mod cdrom pata_acpi uhci_hcd ohci_hcd ehci_hcd Pid: 1868, comm: X Not tainted 2.6.25-rc2-gc-00243-g54a8145 #379 [<c011aff0>] warn_on_slowpath+0x41/0x51 [<c012d674>] ? ktime_get_ts+0x3b/0x3f [<c012d68b>] ? ktime_get+0x13/0x2f [<c011522a>] ? hrtick_start_fair+0xce/0x10a [<c0115571>] ? enqueue_task_fair+0x18a/0x19b [<c01148ef>] ? enqueue_task+0x39/0x45 [<c02b5738>] ? skb_release_data+0x84/0x89 [<c0169634>] ? __slab_free+0x56/0x262 [<c02e0046>] tcp_fastretrans_alert+0xa5/0xa4f [<c02e2089>] tcp_ack+0xba6/0xcf9 [<c02e4b8e>] tcp_rcv_established+0x529/0x5fb [<c02e960e>] tcp_v4_do_rcv+0x28/0x188 [<c02ead20>] tcp_v4_rcv+0x5a2/0x607 [<f8985daf>] ? ipw_rx+0x12b5/0x12bd [ipw2200] [<c02d4165>] ip_local_deliver_finish+0xda/0x16a [<c02d4543>] ip_local_deliver+0x64/0x6d [<c02d406c>] ip_rcv_finish+0x244/0x263 [<c02d44c1>] ip_rcv+0x1d2/0x1f0 [<c02b9e86>] netif_receive_skb+0x34d/0x3d1 [<c02bbc2f>] process_backlog+0x5b/0xa5 [<c02bb849>] net_rx_action+0x86/0x166 [<c011f418>] __do_softirq+0x38/0x7a [<c0106327>] do_softirq+0x3e/0x72 [<c014a0e3>] ? handle_fasteoi_irq+0x0/0xbd [<c011f364>] irq_exit+0x28/0x61 [<c01063f0>] do_IRQ+0x95/0xaa [<c0105293>] common_interrupt+0x23/0x28 ======================= ---[ end trace c3302487bda6288d ]--- KERNEL: assertion (packets <= tp->packets_out) failed at /home/g/linux-2.6/net/ipv4/tcp_input.c (2145) ------------[ cut here ]------------ WARNING: at /home/g/linux-2.6/net/ipv4/tcp_input.c:2515 tcp_fastretrans_alert+0xa5/0xa4f() Modules linked in: usb_storage radeon drm acpi_cpufreq lm90 hwmon binfmt_misc dm_mirror dm_mod snd_intel8x0m snd_intel8x0 snd_seq_dummy snd_ac97_codec ac97_bus snd_seq_oss snd_seq_midi_event snd_seq snd_seq_device snd_pcm_oss snd_mixer_oss snd_pcm snd_timer snd ohci1394 ieee1394 hci_usb ipw2200 bluetooth usbhid ieee80211 firewire_ohci soundcore hid snd_page_alloc sg rtc_cmos i2c_i801 iTCO_wdt serio_raw firewire_core button ac asus_laptop i2c_core rtc_core crc_itu_t irda crc_ccitt battery skge led_class rtc_lib pcspkr ieee80211_crypt sdhci mmc_core sr_mod cdrom pata_acpi uhci_hcd ohci_hcd ehci_hcd Pid: 0, comm: swapper Not tainted 2.6.25-rc2-gc-00243-g54a8145 #379 [<c011aff0>] warn_on_slowpath+0x41/0x51 [<c02e0ae0>] ? tcp_sacktag_walk+0x67/0x2a6 [<c02bc8f1>] ? dev_queue_xmit+0x296/0x2bd [<c02d7709>] ? ip_finish_output+0x1dd/0x218 [<c02bc8f1>] ? dev_queue_xmit+0x296/0x2bd [<c02d7709>] ? ip_finish_output+0x1dd/0x218 [<c0169634>] ? __slab_free+0x56/0x262 [<c02b5738>] ? skb_release_data+0x84/0x89 [<c0169634>] ? __slab_free+0x56/0x262 [<c02e0046>] tcp_fastretrans_alert+0xa5/0xa4f [<c02e2089>] tcp_ack+0xba6/0xcf9 [<c02e4b8e>] tcp_rcv_established+0x529/0x5fb [<c02e960e>] tcp_v4_do_rcv+0x28/0x188 [<c02ead20>] tcp_v4_rcv+0x5a2/0x607 [<f8985daf>] ? ipw_rx+0x12b5/0x12bd [ipw2200] [<c02d4165>] ip_local_deliver_finish+0xda/0x16a [<c02d4543>] ip_local_deliver+0x64/0x6d [<c02d406c>] ip_rcv_finish+0x244/0x263 [<c02d44c1>] ip_rcv+0x1d2/0x1f0 [<c02b9e86>] netif_receive_skb+0x34d/0x3d1 [<c02bbc2f>] process_backlog+0x5b/0xa5 [<c02bb849>] net_rx_action+0x86/0x166 [<c011f418>] __do_softirq+0x38/0x7a [<c0106327>] do_softirq+0x3e/0x72 [<c014a0e3>] ? handle_fasteoi_irq+0x0/0xbd [<c011f364>] irq_exit+0x28/0x61 [<c01063f0>] do_IRQ+0x95/0xaa [<c0105293>] common_interrupt+0x23/0x28 [<c014007b>] ? cgroup_scan_tasks+0x73/0x15b [<c0110000>] ? io_apic_set_pci_routing+0x2b/0x119 [<c023a59c>] ? acpi_idle_enter_simple+0x15b/0x1c7 [<c023a6bb>] acpi_idle_enter_bm+0xb3/0x2cc [<c02acc2b>] cpuidle_idle_call+0x4c/0x71 [<c02acbdf>] ? cpuidle_idle_call+0x0/0x71 [<c0103570>] cpu_idle+0x5a/0x87 [<c0311af8>] rest_init+0x5c/0x5e ======================= ---[ end trace c3302487bda6288d ]--- usb 2-2: USB disconnect, address 4 ------------[ cut here ]------------ WARNING: at /home/g/linux-2.6/net/ipv4/tcp_input.c:2515 tcp_fastretrans_alert+0xa5/0xa4f() Modules linked in: usb_storage radeon drm acpi_cpufreq lm90 hwmon binfmt_misc dm_mirror dm_mod snd_intel8x0m snd_intel8x0 snd_seq_dummy snd_ac97_codec ac97_bus snd_seq_oss snd_seq_midi_event snd_seq snd_seq_device snd_pcm_oss snd_mixer_oss snd_pcm snd_timer snd ohci1394 ieee1394 hci_usb ipw2200 bluetooth usbhid ieee80211 firewire_ohci soundcore hid snd_page_alloc sg rtc_cmos i2c_i801 iTCO_wdt serio_raw firewire_core button ac asus_laptop i2c_core rtc_core crc_itu_t irda crc_ccitt battery skge led_class rtc_lib pcspkr ieee80211_crypt sdhci mmc_core sr_mod cdrom pata_acpi uhci_hcd ohci_hcd ehci_hcd Pid: 0, comm: swapper Not tainted 2.6.25-rc2-gc-00243-g54a8145 #379 [<c011aff0>] warn_on_slowpath+0x41/0x51 [<c02e0ae0>] ? tcp_sacktag_walk+0x67/0x2a6 [<c02bc8f1>] ? dev_queue_xmit+0x296/0x2bd [<c02d7709>] ? ip_finish_output+0x1dd/0x218 [<c02bc8f1>] ? dev_queue_xmit+0x296/0x2bd [<c02d7709>] ? ip_finish_output+0x1dd/0x218 [<c0169634>] ? __slab_free+0x56/0x262 [<c030090a>] ? bictcp_cong_avoid+0x39/0x305 [<c0169634>] ? __slab_free+0x56/0x262 [<c02e0046>] tcp_fastretrans_alert+0xa5/0xa4f [<c02e2089>] tcp_ack+0xba6/0xcf9 [<c02e4740>] tcp_rcv_established+0xdb/0x5fb [<c02e960e>] tcp_v4_do_rcv+0x28/0x188 [<c02ead20>] tcp_v4_rcv+0x5a2/0x607 [<f8985daf>] ? ipw_rx+0x12b5/0x12bd [ipw2200] [<c02d4165>] ip_local_deliver_finish+0xda/0x16a [<c02d4543>] ip_local_deliver+0x64/0x6d [<c02d406c>] ip_rcv_finish+0x244/0x263 [<c02d44c1>] ip_rcv+0x1d2/0x1f0 [<c02b9e86>] netif_receive_skb+0x34d/0x3d1 [<c02bbc2f>] process_backlog+0x5b/0xa5 [<c02bb849>] net_rx_action+0x86/0x166 [<c011f418>] __do_softirq+0x38/0x7a [<c0106327>] do_softirq+0x3e/0x72 [<c014a0e3>] ? handle_fasteoi_irq+0x0/0xbd [<c011f364>] irq_exit+0x28/0x61 [<c01063f0>] do_IRQ+0x95/0xaa [<c0105293>] common_interrupt+0x23/0x28 [<c014007b>] ? cgroup_scan_tasks+0x73/0x15b [<c0110000>] ? io_apic_set_pci_routing+0x2b/0x119 [<c023a59c>] ? acpi_idle_enter_simple+0x15b/0x1c7 [<c023a6bb>] acpi_idle_enter_bm+0xb3/0x2cc [<c02acc2b>] cpuidle_idle_call+0x4c/0x71 [<c02acbdf>] ? cpuidle_idle_call+0x0/0x71 [<c0103570>] cpu_idle+0x5a/0x87 [<c0311af8>] rest_init+0x5c/0x5e ======================= ---[ end trace c3302487bda6288d ]--- ------------[ cut here ]------------ WARNING: at /home/g/linux-2.6/net/ipv4/tcp_input.c:2515 tcp_fastretrans_alert+0xa5/0xa4f() Modules linked in: usb_storage radeon drm acpi_cpufreq lm90 hwmon binfmt_misc dm_mirror dm_mod snd_intel8x0m snd_intel8x0 snd_seq_dummy snd_ac97_codec ac97_bus snd_seq_oss snd_seq_midi_event snd_seq snd_seq_device snd_pcm_oss snd_mixer_oss snd_pcm snd_timer snd ohci1394 ieee1394 hci_usb ipw2200 bluetooth usbhid ieee80211 firewire_ohci soundcore hid snd_page_alloc sg rtc_cmos i2c_i801 iTCO_wdt serio_raw firewire_core button ac asus_laptop i2c_core rtc_core crc_itu_t irda crc_ccitt battery skge led_class rtc_lib pcspkr ieee80211_crypt sdhci mmc_core sr_mod cdrom pata_acpi uhci_hcd ohci_hcd ehci_hcd Pid: 0, comm: swapper Not tainted 2.6.25-rc2-gc-00243-g54a8145 #379 [<c011aff0>] warn_on_slowpath+0x41/0x51 [<c02e0ae0>] ? tcp_sacktag_walk+0x67/0x2a6 [<c02bc8f1>] ? dev_queue_xmit+0x296/0x2bd [<c02d7709>] ? ip_finish_output+0x1dd/0x218 [<c012ed5c>] ? getnstimeofday+0x2f/0xb4 [<c012d674>] ? ktime_get_ts+0x3b/0x3f [<c012d68b>] ? ktime_get+0x13/0x2f [<c02b5738>] ? skb_release_data+0x84/0x89 [<c0169634>] ? __slab_free+0x56/0x262 [<c02e0046>] tcp_fastretrans_alert+0xa5/0xa4f [<c02e2089>] tcp_ack+0xba6/0xcf9 [<c02e4b8e>] tcp_rcv_established+0x529/0x5fb [<c02e960e>] tcp_v4_do_rcv+0x28/0x188 [<c02ead20>] tcp_v4_rcv+0x5a2/0x607 [<f8985daf>] ? ipw_rx+0x12b5/0x12bd [ipw2200] [<c02d4165>] ip_local_deliver_finish+0xda/0x16a [<c02d4543>] ip_local_deliver+0x64/0x6d [<c02d406c>] ip_rcv_finish+0x244/0x263 [<c02d44c1>] ip_rcv+0x1d2/0x1f0 [<c02b9e86>] netif_receive_skb+0x34d/0x3d1 [<c02bbc2f>] process_backlog+0x5b/0xa5 [<c02bb849>] net_rx_action+0x86/0x166 [<c011f418>] __do_softirq+0x38/0x7a [<c0106327>] do_softirq+0x3e/0x72 [<c014a0e3>] ? handle_fasteoi_irq+0x0/0xbd [<c011f364>] irq_exit+0x28/0x61 [<c01063f0>] do_IRQ+0x95/0xaa [<c0105293>] common_interrupt+0x23/0x28 [<c014007b>] ? cgroup_scan_tasks+0x73/0x15b [<c0110000>] ? io_apic_set_pci_routing+0x2b/0x119 [<c023a59c>] ? acpi_idle_enter_simple+0x15b/0x1c7 [<c023a6bb>] acpi_idle_enter_bm+0xb3/0x2cc [<c02acc2b>] cpuidle_idle_call+0x4c/0x71 [<c02acbdf>] ? cpuidle_idle_call+0x0/0x71 [<c0103570>] cpu_idle+0x5a/0x87 [<c0311af8>] rest_init+0x5c/0x5e ======================= ---[ end trace c3302487bda6288d ]--- usb 2-2: new low speed USB device using uhci_hcd and address 5 usb 2-2: configuration #1 chosen from 1 choice input: Logitech Optical USB Mouse as /class/input/input10 input,hidraw0: USB HID v1.10 Mouse [Logitech Optical USB Mouse] on usb-0000:00:1d.0-2 usb 2-2: New USB device found, idVendor=046d, idProduct=c016 usb 2-2: New USB device strings: Mfr=1, Product=2, SerialNumber=0 usb 2-2: Product: Optical USB Mouse usb 2-2: Manufacturer: Logitech ipw2200: Failed to send SYSTEM_CONFIG: Command timed out. ipw2200: Firmware error detected. Restarting. ipw2200: Failed to send SYSTEM_CONFIG: Command timed out. ipw2200: Failed to send SCAN_ABORT: Command timed out. usb 2-2: USB disconnect, address 5 ipw2200: Firmware error detected. Restarting. ipw2200: Failed to send SYSTEM_CONFIG: Command timed out. usb 2-2: new low speed USB device using uhci_hcd and address 6 usb 2-2: configuration #1 chosen from 1 choice input: Logitech Optical USB Mouse as /class/input/input11 input,hidraw0: USB HID v1.10 Mouse [Logitech Optical USB Mouse] on usb-0000:00:1d.0-2 usb 2-2: New USB device found, idVendor=046d, idProduct=c016 usb 2-2: New USB device strings: Mfr=1, Product=2, SerialNumber=0 usb 2-2: Product: Optical USB Mouse usb 2-2: Manufacturer: Logitech Adding 3478064k swap on /dev/sda2. Priority:-2 extents:1 across:3478064k usb 2-2: USB disconnect, address 6 TCP: Treason uncloaked! Peer 86.136.188.142:54678/43160 shrinks window 4022990550:4022993333. Repaired. TCP: Treason uncloaked! Peer 86.136.188.142:54678/43160 shrinks window 4022990550:4022993333. Repaired. ------------[ cut here ]------------ WARNING: at /home/g/linux-2.6/net/ipv4/tcp_input.c:2515 tcp_fastretrans_alert+0xa5/0xa4f() Modules linked in: usb_storage radeon drm acpi_cpufreq lm90 hwmon binfmt_misc dm_mirror dm_mod snd_intel8x0m snd_intel8x0 snd_seq_dummy snd_ac97_codec ac97_bus snd_seq_oss snd_seq_midi_event snd_seq snd_seq_device snd_pcm_oss snd_mixer_oss snd_pcm snd_timer snd ohci1394 ieee1394 hci_usb ipw2200 bluetooth usbhid ieee80211 firewire_ohci soundcore hid snd_page_alloc sg rtc_cmos i2c_i801 iTCO_wdt serio_raw firewire_core button ac asus_laptop i2c_core rtc_core crc_itu_t irda crc_ccitt battery skge led_class rtc_lib pcspkr ieee80211_crypt sdhci mmc_core sr_mod cdrom pata_acpi uhci_hcd ohci_hcd ehci_hcd Pid: 0, comm: swapper Not tainted 2.6.25-rc2-gc-00243-g54a8145 #379 [<c011aff0>] warn_on_slowpath+0x41/0x51 [<c02c0066>] ? neigh_seq_start+0x2e/0xa0 [<c02bc8f1>] ? dev_queue_xmit+0x296/0x2bd [<c02d7709>] ? ip_finish_output+0x1dd/0x218 [<c02d7cbf>] ? ip_output+0x8e/0x95 [<c02d7257>] ? ip_local_out+0x18/0x1b [<c02d7f48>] ? ip_queue_xmit+0x282/0x2d2 [<c012d674>] ? ktime_get_ts+0x3b/0x3f [<c0115044>] ? __enqueue_entity+0x9c/0xa4 [<c02b5738>] ? skb_release_data+0x84/0x89 [<c016a004>] ? kfree+0x6e/0x7a [<c02b5738>] ? skb_release_data+0x84/0x89 [<c02e0046>] tcp_fastretrans_alert+0xa5/0xa4f [<c02e2089>] tcp_ack+0xba6/0xcf9 [<c02e4b8e>] tcp_rcv_established+0x529/0x5fb [<c02e960e>] tcp_v4_do_rcv+0x28/0x188 [<c02ead20>] tcp_v4_rcv+0x5a2/0x607 [<f8985daf>] ? ipw_rx+0x12b5/0x12bd [ipw2200] [<c02d4165>] ip_local_deliver_finish+0xda/0x16a [<c02d4543>] ip_local_deliver+0x64/0x6d [<c02d406c>] ip_rcv_finish+0x244/0x263 [<c02d44c1>] ip_rcv+0x1d2/0x1f0 [<c02b9e86>] netif_receive_skb+0x34d/0x3d1 [<c02bbc2f>] process_backlog+0x5b/0xa5 [<c02bb849>] net_rx_action+0x86/0x166 [<c011f418>] __do_softirq+0x38/0x7a [<c0106327>] do_softirq+0x3e/0x72 [<c014a0e3>] ? handle_fasteoi_irq+0x0/0xbd [<c011f364>] irq_exit+0x28/0x61 [<c01063f0>] do_IRQ+0x95/0xaa [<c0105293>] common_interrupt+0x23/0x28 [<c014007b>] ? cgroup_scan_tasks+0x73/0x15b [<c0110000>] ? io_apic_set_pci_routing+0x2b/0x119 [<c023a865>] ? acpi_idle_enter_bm+0x25d/0x2cc [<c02acc2b>] cpuidle_idle_call+0x4c/0x71 [<c02acbdf>] ? cpuidle_idle_call+0x0/0x71 [<c0103570>] cpu_idle+0x5a/0x87 [<c0311af8>] rest_init+0x5c/0x5e ======================= ---[ end trace c3302487bda6288d ]--- ipw2200: Failed to send SYSTEM_CONFIG: Command timed out. ipw2200: Firmware error detected. Restarting. TCP: Treason uncloaked! Peer 86.136.188.142:54678/42938 shrinks window 3487438366:3487439840. Repaired. ipw2200: Firmware error detected. Restarting. ------------[ cut here ]------------ WARNING: at /home/g/linux-2.6/net/ipv4/tcp_input.c:2515 tcp_fastretrans_alert+0xa5/0xa4f() Modules linked in: usb_storage radeon drm acpi_cpufreq lm90 hwmon binfmt_misc dm_mirror dm_mod snd_intel8x0m snd_intel8x0 snd_seq_dummy snd_ac97_codec ac97_bus snd_seq_oss snd_seq_midi_event snd_seq snd_seq_device snd_pcm_oss snd_mixer_oss snd_pcm snd_timer snd ohci1394 ieee1394 hci_usb ipw2200 bluetooth usbhid ieee80211 firewire_ohci soundcore hid snd_page_alloc sg rtc_cmos i2c_i801 iTCO_wdt serio_raw firewire_core button ac asus_laptop i2c_core rtc_core crc_itu_t irda crc_ccitt battery skge led_class rtc_lib pcspkr ieee80211_crypt sdhci mmc_core sr_mod cdrom pata_acpi uhci_hcd ohci_hcd ehci_hcd Pid: 0, comm: swapper Not tainted 2.6.25-rc2-gc-00243-g54a8145 #379 [<c011aff0>] warn_on_slowpath+0x41/0x51 [<c02c0066>] ? neigh_seq_start+0x2e/0xa0 [<c02bc8f1>] ? dev_queue_xmit+0x296/0x2bd [<c02d7709>] ? ip_finish_output+0x1dd/0x218 [<c02d7cbf>] ? ip_output+0x8e/0x95 [<c02e13c2>] ? tcp_sacktag_write_queue+0x6a3/0x7c4 [<c0152c7e>] ? free_hot_page+0xa/0xc [<c0152c9a>] ? __free_pages+0x1a/0x25 [<c03008e4>] ? bictcp_cong_avoid+0x13/0x305 [<c02e0046>] tcp_fastretrans_alert+0xa5/0xa4f [<c02e2089>] tcp_ack+0xba6/0xcf9 [<c02e4b8e>] tcp_rcv_established+0x529/0x5fb [<c02e960e>] tcp_v4_do_rcv+0x28/0x188 [<c02ead20>] tcp_v4_rcv+0x5a2/0x607 [<f8985daf>] ? ipw_rx+0x12b5/0x12bd [ipw2200] [<c02d4165>] ip_local_deliver_finish+0xda/0x16a [<c02d4543>] ip_local_deliver+0x64/0x6d [<c02d406c>] ip_rcv_finish+0x244/0x263 [<c02d44c1>] ip_rcv+0x1d2/0x1f0 [<c02b9e86>] netif_receive_skb+0x34d/0x3d1 [<c02bbc2f>] process_backlog+0x5b/0xa5 [<c02bb849>] net_rx_action+0x86/0x166 [<c011f418>] __do_softirq+0x38/0x7a [<c0106327>] do_softirq+0x3e/0x72 [<c014a0e3>] ? handle_fasteoi_irq+0x0/0xbd [<c011f364>] irq_exit+0x28/0x61 [<c01063f0>] do_IRQ+0x95/0xaa [<c0105293>] common_interrupt+0x23/0x28 [<c014007b>] ? cgroup_scan_tasks+0x73/0x15b [<c0110000>] ? io_apic_set_pci_routing+0x2b/0x119 [<c023a59c>] ? acpi_idle_enter_simple+0x15b/0x1c7 [<c023a6bb>] acpi_idle_enter_bm+0xb3/0x2cc [<c02acc2b>] cpuidle_idle_call+0x4c/0x71 [<c02acbdf>] ? cpuidle_idle_call+0x0/0x71 [<c0103570>] cpu_idle+0x5a/0x87 [<c0311af8>] rest_init+0x5c/0x5e ======================= ---[ end trace c3302487bda6288d ]--- ipw2200: Failed to send SYSTEM_CONFIG: Command timed out. ^ permalink raw reply related [flat|nested] 20+ messages in thread
* Re: WARNING: at net/ipv4/tcp_input.c:2054 tcp_mark_head_lost() 2008-02-27 18:56 ` Guillaume Chazarain @ 2008-02-27 19:29 ` Ilpo Järvinen 2008-02-28 8:22 ` Ilpo Järvinen 0 siblings, 1 reply; 20+ messages in thread From: Ilpo Järvinen @ 2008-02-27 19:29 UTC (permalink / raw) To: Guillaume Chazarain; +Cc: Giangiacomo Mariotti, LKML, Netdev, Andrew Morton [-- Warning: decoded text below may be mangled, UTF-8 assumed --] [-- Attachment #1: Type: TEXT/PLAIN; charset=utf-8, Size: 1047 bytes --] On Wed, 27 Feb 2008, Guillaume Chazarain wrote: > On Wed, Feb 27, 2008 at 10:29 AM, Ilpo Järvinen > <ilpo.jarvinen@helsinki.fi> wrote: > > I did in the past a debug patch > > that verifies TCP's write queue state by the hard way, ie., by > > bruteforce > > walking often enough to catch inconsistencies early enough to find > > out > > the root cause. > > Are you talking about this one: > http://marc.info/?l=linux-netdev&m=119482084511178 ? > I attached a forward port to current git. No, I'd much more complete set of tests than in that one. > I am using this patch, and caught this maybe related error while > Bittorrenting: > > KERNEL: assertion (packets <= tp->packets_out) failed at > /home/g/linux-2.6/net/ipv4/tcp_input.c (2145) > KERNEL: assertion (packets <= tp->packets_out) failed at > /home/g/linux-2.6/net/ipv4/tcp_input.c (2145) > ------------[ cut here ]------------ > WARNING: at /home/g/linux-2.6/net/ipv4/tcp_input.c:2515 > tcp_fastretrans_alert+0xa5/0xa4f() You seem to be good in catching these... :-) -- i. ^ permalink raw reply [flat|nested] 20+ messages in thread
* Re: WARNING: at net/ipv4/tcp_input.c:2054 tcp_mark_head_lost() 2008-02-27 19:29 ` Ilpo Järvinen @ 2008-02-28 8:22 ` Ilpo Järvinen 2008-02-29 1:10 ` Andrew Morton 2008-03-02 12:20 ` Guillaume Chazarain 0 siblings, 2 replies; 20+ messages in thread From: Ilpo Järvinen @ 2008-02-28 8:22 UTC (permalink / raw) To: Guillaume Chazarain; +Cc: Giangiacomo Mariotti, LKML, Netdev, Andrew Morton [-- Warning: decoded text below may be mangled, UTF-8 assumed --] [-- Attachment #1: Type: TEXT/PLAIN; charset=utf-8, Size: 10469 bytes --] On Wed, 27 Feb 2008, Ilpo Järvinen wrote: > On Wed, 27 Feb 2008, Guillaume Chazarain wrote: > > > Are you talking about this one: > > http://marc.info/?l=linux-netdev&m=119482084511178 ? > > I attached a forward port to current git. > > No, I'd much more complete set of tests than in that one. This below is for 2.6.25-rcs, won't work in 2.6.24, I'll customize it for that soon. Hopefully there isn't anything stupid in it (this time) which makes it to trigger spuriously. -- i. [PATCH] TCP debug S+L (for 2.6.25-rcs, incompatible with 2.6.24.y) --- include/net/tcp.h | 9 +++- net/ipv4/tcp_input.c | 18 +++++++- net/ipv4/tcp_ipv4.c | 127 +++++++++++++++++++++++++++++++++++++++++++++++++ net/ipv4/tcp_output.c | 23 +++++++-- 4 files changed, 169 insertions(+), 8 deletions(-) diff --git a/include/net/tcp.h b/include/net/tcp.h index 7de4ea3..acf5546 100644 --- a/include/net/tcp.h +++ b/include/net/tcp.h @@ -272,6 +272,9 @@ DECLARE_SNMP_STAT(struct tcp_mib, tcp_statistics); #define TCP_ADD_STATS_BH(field, val) SNMP_ADD_STATS_BH(tcp_statistics, field, val) #define TCP_ADD_STATS_USER(field, val) SNMP_ADD_STATS_USER(tcp_statistics, field, val) +extern void tcp_print_queue(struct sock *sk); +extern void tcp_verify_wq(struct sock *sk); + extern void tcp_v4_err(struct sk_buff *skb, u32); extern void tcp_shutdown (struct sock *sk, int how); @@ -768,7 +771,11 @@ static inline __u32 tcp_current_ssthresh(const struct sock *sk) } /* Use define here intentionally to get WARN_ON location shown at the caller */ -#define tcp_verify_left_out(tp) WARN_ON(tcp_left_out(tp) > tp->packets_out) +#define tcp_verify_left_out(tp) \ + do {\ + WARN_ON(tcp_left_out(tp) > tp->packets_out); \ + tcp_verify_wq((struct sock *)tp); \ + } while(0) extern void tcp_enter_cwr(struct sock *sk, const int set_ssthresh); extern __u32 tcp_init_cwnd(struct tcp_sock *tp, struct dst_entry *dst); diff --git a/net/ipv4/tcp_input.c b/net/ipv4/tcp_input.c index 19c449f..c897c93 100644 --- a/net/ipv4/tcp_input.c +++ b/net/ipv4/tcp_input.c @@ -1426,8 +1426,10 @@ tcp_sacktag_write_queue(struct sock *sk, struct sk_buff *ack_skb, int first_sack_index; if (!tp->sacked_out) { - if (WARN_ON(tp->fackets_out)) + if (WARN_ON(tp->fackets_out)) { + tcp_verify_left_out(tp); tp->fackets_out = 0; + } tcp_highest_sack_reset(sk); } @@ -2136,6 +2138,8 @@ static void tcp_mark_head_lost(struct sock *sk, int packets, int fast_rexmit) struct sk_buff *skb; int cnt; + tcp_verify_left_out(tp); + BUG_TRAP(packets <= tp->packets_out); if (tp->lost_skb_hint) { skb = tp->lost_skb_hint; @@ -2501,6 +2505,8 @@ static void tcp_fastretrans_alert(struct sock *sk, int pkts_acked, int flag) (tcp_fackets_out(tp) > tp->reordering)); int fast_rexmit = 0; + tcp_verify_left_out(tp); + if (WARN_ON(!tp->packets_out && tp->sacked_out)) tp->sacked_out = 0; if (WARN_ON(!tp->sacked_out && tp->fackets_out)) @@ -2645,6 +2651,10 @@ static void tcp_fastretrans_alert(struct sock *sk, int pkts_acked, int flag) if (do_lost || (tcp_is_fack(tp) && tcp_head_timedout(sk))) tcp_update_scoreboard(sk, fast_rexmit); tcp_cwnd_down(sk, flag); + + WARN_ON(tcp_write_queue_head(sk) == NULL); + WARN_ON(!tp->packets_out); + tcp_xmit_retransmit_queue(sk); } @@ -2848,6 +2858,8 @@ static int tcp_clean_rtx_queue(struct sock *sk, int prior_fackets) tcp_clear_all_retrans_hints(tp); } + tcp_verify_left_out(tp); + if (skb && (TCP_SKB_CB(skb)->sacked & TCPCB_SACKED_ACKED)) flag |= FLAG_SACK_RENEGING; @@ -3175,6 +3187,8 @@ static int tcp_ack(struct sock *sk, struct sk_buff *skb, int flag) prior_fackets = tp->fackets_out; prior_in_flight = tcp_packets_in_flight(tp); + tcp_verify_left_out(tp); + if (!(flag & FLAG_SLOWPATH) && after(ack, prior_snd_una)) { /* Window is constant, pure forward advance. * No more checks are required. @@ -3237,6 +3251,8 @@ static int tcp_ack(struct sock *sk, struct sk_buff *skb, int flag) if ((flag & FLAG_FORWARD_PROGRESS) || !(flag & FLAG_NOT_DUP)) dst_confirm(sk->sk_dst_cache); + tcp_verify_left_out(tp); + return 1; no_queue: diff --git a/net/ipv4/tcp_ipv4.c b/net/ipv4/tcp_ipv4.c index 00156bf..71a4646 100644 --- a/net/ipv4/tcp_ipv4.c +++ b/net/ipv4/tcp_ipv4.c @@ -108,6 +108,133 @@ struct inet_hashinfo __cacheline_aligned tcp_hashinfo = { .lhash_wait = __WAIT_QUEUE_HEAD_INITIALIZER(tcp_hashinfo.lhash_wait), }; +void tcp_print_queue(struct sock *sk) +{ + struct tcp_sock *tp = tcp_sk(sk); + struct sk_buff *skb; + char s[50+1]; + char h[50+1]; + int idx = 0; + int i; + + i = 0; + tcp_for_write_queue(skb, sk) { + if (skb == tcp_send_head(sk)) + printk(KERN_ERR "head %u %p\n", i, skb); + else + printk(KERN_ERR "skb %u %p\n", i, skb); + i++; + } + + tcp_for_write_queue(skb, sk) { + if (skb == tcp_send_head(sk)) + break; + + for (i = 0; i < tcp_skb_pcount(skb); i++) { + if (TCP_SKB_CB(skb)->sacked & TCPCB_SACKED_ACKED) { + s[idx] = 'S'; + if (TCP_SKB_CB(skb)->sacked & TCPCB_LOST) + s[idx] = 'B'; + + } else if (TCP_SKB_CB(skb)->sacked & TCPCB_LOST) { + s[idx] = 'L'; + } else { + s[idx] = ' '; + } + if (s[idx] != ' ' && skb->len < tp->mss_cache) + s[idx] += 'a' - 'A'; + + if (i == 0) { + if (skb == tcp_highest_sack(sk)) + h[idx] = 'h'; + else + h[idx] = '+'; + } else { + h[idx] = '-'; + } + + if (++idx >= 50) { + s[idx] = 0; + h[idx] = 0; + printk(KERN_ERR "TCP wq(s) %s\n", s); + printk(KERN_ERR "TCP wq(h) %s\n", h); + idx = 0; + } + } + } + if (idx) { + s[idx] = '<'; + s[idx+1] = 0; + h[idx] = '<'; + h[idx+1] = 0; + printk(KERN_ERR "TCP wq(s) %s\n", s); + printk(KERN_ERR "TCP wq(h) %s\n", h); + } + printk(KERN_ERR "l%u s%u f%u p%u seq: su%u hs%u sn%u\n", + tp->lost_out, tp->sacked_out, tp->fackets_out, tp->packets_out, + tp->snd_una, tcp_highest_sack_seq(tp), tp->snd_nxt); +} + +void tcp_verify_wq(struct sock *sk) +{ + struct tcp_sock *tp = tcp_sk(sk); + u32 lost = 0; + u32 sacked = 0; + u32 packets = 0; + u32 fackets = 0; + int hs_valid = 0; + struct sk_buff *skb; + + tcp_for_write_queue(skb, sk) { + if (skb == tcp_send_head(sk)) + break; + + if ((fackets == packets) && (skb == tp->highest_sack)) + hs_valid = 1; + + packets += tcp_skb_pcount(skb); + + if (TCP_SKB_CB(skb)->sacked & TCPCB_SACKED_ACKED) { + sacked += tcp_skb_pcount(skb); + if (TCP_SKB_CB(skb)->sacked & TCPCB_LOST) + printk(KERN_ERR "Sacked bitmap S+L: %u %u-%u/%u\n", + TCP_SKB_CB(skb)->sacked, + TCP_SKB_CB(skb)->end_seq - tp->snd_una, + TCP_SKB_CB(skb)->seq - tp->snd_una, + tp->snd_una); + fackets = packets; + hs_valid = 0; + } + if (TCP_SKB_CB(skb)->sacked & TCPCB_LOST) + lost += tcp_skb_pcount(skb); + } + + if ((fackets == packets) && (tp->highest_sack == tcp_send_head(sk))) + hs_valid = 1; + + if ((lost != tp->lost_out) || + (tcp_is_sack(tp) && (sacked != tp->sacked_out)) || + ((sacked || (tcp_is_sack(tp) && tp->sacked_out)) && !hs_valid) || + (packets != tp->packets_out) || + (fackets != tp->fackets_out) || + tcp_left_out(tp) > tp->packets_out) { + printk(KERN_ERR "P: %u L: %u vs %u S: %u vs %u F: %u vs %u w: %u-%u (%u)\n", + tp->packets_out, + lost, tp->lost_out, + sacked, tp->sacked_out, + fackets, tp->fackets_out, + tp->snd_una, tp->snd_nxt, + tp->rx_opt.sack_ok); + tcp_print_queue(sk); + } + + WARN_ON(lost != tp->lost_out); + WARN_ON(tcp_is_sack(tp) && (sacked != tp->sacked_out)); + WARN_ON(packets != tp->packets_out); + WARN_ON(fackets != tp->fackets_out); + WARN_ON(tcp_left_out(tp) > tp->packets_out); +} + static inline __u32 tcp_v4_init_sequence(struct sk_buff *skb) { return secure_tcp_sequence_number(ip_hdr(skb)->daddr, diff --git a/net/ipv4/tcp_output.c b/net/ipv4/tcp_output.c index ed750f9..257de86 100644 --- a/net/ipv4/tcp_output.c +++ b/net/ipv4/tcp_output.c @@ -779,10 +779,9 @@ int tcp_fragment(struct sock *sk, struct sk_buff *skb, u32 len, tp->lost_out -= diff; /* Adjust Reno SACK estimate. */ - if (tcp_is_reno(tp) && diff > 0) { + if (tcp_is_reno(tp) && diff > 0) tcp_dec_pcount_approx_int(&tp->sacked_out, diff); - tcp_verify_left_out(tp); - } + tcp_adjust_fackets_out(sk, skb, diff); } @@ -790,6 +789,8 @@ int tcp_fragment(struct sock *sk, struct sk_buff *skb, u32 len, skb_header_release(buff); tcp_insert_write_queue_after(skb, buff, sk); + tcp_verify_left_out(tp); + return 0; } @@ -1463,6 +1464,7 @@ static int tcp_write_xmit(struct sock *sk, unsigned int mss_now, int nonagle) } else if (result > 0) { sent_pkts = 1; } + tcp_verify_left_out(tp); while ((skb = tcp_send_head(sk))) { unsigned int limit; @@ -1764,6 +1766,7 @@ static void tcp_retrans_try_collapse(struct sock *sk, struct sk_buff *skb, tcp_clear_retrans_hints_partial(tp); sk_wmem_free_skb(sk, next_skb); + tcp_verify_left_out(tp); } /* Do a simple retransmit without using the backoff mechanisms in @@ -1795,13 +1798,13 @@ void tcp_simple_retransmit(struct sock *sk) } } + tcp_verify_left_out(tp); + tcp_clear_all_retrans_hints(tp); if (!lost) return; - tcp_verify_left_out(tp); - /* Don't muck with the congestion window here. * Reason is that we do not increase amount of _data_ * in network, but units changed and effective @@ -1888,6 +1891,8 @@ int tcp_retransmit_skb(struct sock *sk, struct sk_buff *skb) tcp_init_nondata_skb(skb, TCP_SKB_CB(skb)->end_seq - 1, TCP_SKB_CB(skb)->flags); skb->ip_summed = CHECKSUM_NONE; + + tcp_verify_left_out(tp); } } @@ -1970,8 +1975,10 @@ void tcp_xmit_retransmit_queue(struct sock *sk) * packet to be MSS sized and all the * packet counting works out. */ - if (tcp_packets_in_flight(tp) >= tp->snd_cwnd) + if (tcp_packets_in_flight(tp) >= tp->snd_cwnd) { + tcp_verify_left_out(tp); return; + } if (sacked & TCPCB_LOST) { if (!(sacked & (TCPCB_SACKED_ACKED|TCPCB_SACKED_RETRANS))) { @@ -1997,6 +2004,8 @@ void tcp_xmit_retransmit_queue(struct sock *sk) } } + tcp_verify_left_out(tp); + /* OK, demanded retransmission is finished. */ /* Forward retransmissions are possible only during Recovery. */ @@ -2054,6 +2063,8 @@ void tcp_xmit_retransmit_queue(struct sock *sk) NET_INC_STATS_BH(LINUX_MIB_TCPFORWARDRETRANS); } + + tcp_verify_left_out(tp); } /* Send a fin. The caller locks the socket for us. This cannot be -- 1.5.2.2 ^ permalink raw reply related [flat|nested] 20+ messages in thread
* Re: WARNING: at net/ipv4/tcp_input.c:2054 tcp_mark_head_lost() 2008-02-28 8:22 ` Ilpo Järvinen @ 2008-02-29 1:10 ` Andrew Morton 2008-02-29 4:35 ` Bill Fink 2008-03-02 12:20 ` Guillaume Chazarain 1 sibling, 1 reply; 20+ messages in thread From: Andrew Morton @ 2008-02-29 1:10 UTC (permalink / raw) To: "Ilpo Järvinen" Cc: Guillaume Chazarain, Giangiacomo Mariotti, LKML, Netdev On Thu, 28 Feb 2008 10:22:27 +0200 (EET) "Ilpo Järvinen" <ilpo.jarvinen@helsinki.fi> wrote: > [PATCH] TCP debug S+L (for 2.6.25-rcs, incompatible with 2.6.24.y) > > --- > include/net/tcp.h | 9 +++- > net/ipv4/tcp_input.c | 18 +++++++- > net/ipv4/tcp_ipv4.c | 127 +++++++++++++++++++++++++++++++++++++++++++++++++ > net/ipv4/tcp_output.c | 23 +++++++-- I'll put this in -mm, see if we can flush anything out. Please let me know if/when it's obsolete, updated, etc. What is "S+L"? ^ permalink raw reply [flat|nested] 20+ messages in thread
* Re: WARNING: at net/ipv4/tcp_input.c:2054 tcp_mark_head_lost() 2008-02-29 1:10 ` Andrew Morton @ 2008-02-29 4:35 ` Bill Fink 2008-02-29 12:24 ` Ilpo Järvinen 0 siblings, 1 reply; 20+ messages in thread From: Bill Fink @ 2008-02-29 4:35 UTC (permalink / raw) To: Andrew Morton Cc: Ilpo Järvinen , Guillaume Chazarain, Giangiacomo Mariotti, LKML, Netdev On Thu, 28 Feb 2008, Andrew Morton wrote: > On Thu, 28 Feb 2008 10:22:27 +0200 (EET) "Ilpo Järvinen" <ilpo.jarvinen@helsinki.fi> wrote: > > > [PATCH] TCP debug S+L (for 2.6.25-rcs, incompatible with 2.6.24.y) > > > > --- > > include/net/tcp.h | 9 +++- > > net/ipv4/tcp_input.c | 18 +++++++- > > net/ipv4/tcp_ipv4.c | 127 +++++++++++++++++++++++++++++++++++++++++++++++++ > > net/ipv4/tcp_output.c | 23 +++++++-- > > I'll put this in -mm, see if we can flush anything out. Please let me know > if/when it's obsolete, updated, etc. > > What is "S+L"? I'll let Ilpo give the definitive answer. But to test if I'm starting to grasp this, I'll give my understanding. I believe 'S' means that a transmitted TCP skb has been acknowledged by a SACK, while 'L' means that a transmitted SKB is believed lost. Since the 'S' state implies that the packet has actually been successfully received, it should not be possible for it to be considered lost ('L' state). Thus an "S+L" state for a TCP skb is an internally inconsistent state and an indication of a TCP bug. Anyone feel free to correct me if I'm way off base in my understanding. -Bill ^ permalink raw reply [flat|nested] 20+ messages in thread
* Re: WARNING: at net/ipv4/tcp_input.c:2054 tcp_mark_head_lost() 2008-02-29 4:35 ` Bill Fink @ 2008-02-29 12:24 ` Ilpo Järvinen 0 siblings, 0 replies; 20+ messages in thread From: Ilpo Järvinen @ 2008-02-29 12:24 UTC (permalink / raw) To: Bill Fink, Andrew Morton Cc: Guillaume Chazarain, Giangiacomo Mariotti, LKML, Netdev [-- Attachment #1: Type: TEXT/PLAIN, Size: 2718 bytes --] On Thu, 28 Feb 2008, Bill Fink wrote: > On Thu, 28 Feb 2008, Andrew Morton wrote: > > > On Thu, 28 Feb 2008 10:22:27 +0200 (EET) "Ilpo Järvinen" <ilpo.jarvinen@helsinki.fi> wrote: > > > > > [PATCH] TCP debug S+L (for 2.6.25-rcs, incompatible with 2.6.24.y) > > > > > > --- > > > include/net/tcp.h | 9 +++- > > > net/ipv4/tcp_input.c | 18 +++++++- > > > net/ipv4/tcp_ipv4.c | 127 +++++++++++++++++++++++++++++++++++++++++++++++++ > > > net/ipv4/tcp_output.c | 23 +++++++-- > > > > I'll put this in -mm, see if we can flush anything out. Ok, thanks. Were you aware of the considerable cpu consumption it will cause...? I.e., scanning throught the write queue in a number of place per ACK will certainly show up if somebody tests with netperf or so... ;-) ...Just please make sure it won't leak into mainline (for sure you would have done that without this explicit note :-)). Good thing in that debug patch is that it catches inconsistencies immediately when they happen even if the cheap trap (which is in mainline) wouldn't ever see them because the situation would correct itself due to some other event. > > Please let me know if/when it's obsolete, updated, etc. Ok. Since many seem to now reporting this, I suppose the cause is relatively easy to find. > > What is "S+L"? > > I'll let Ilpo give the definitive answer. But to test if I'm starting > to grasp this, I'll give my understanding. I believe 'S' means that a > transmitted TCP skb has been acknowledged by a SACK, while 'L' means > that a transmitted SKB is believed lost. Since the 'S' state implies > that the packet has actually been successfully received, it should not be > possible for it to be considered lost ('L' state). Thus an "S+L" state > for a TCP skb is an internally inconsistent state and an indication of > a TCP bug. > > Anyone feel free to correct me if I'm way off base in my understanding. Yes, this is exactly what it means. There's a big comment about them in the net/ipv4/tcp_input.c too. I answered to a similar question (but Bill mostly told all of it already): http://marc.info/?l=linux-netdev&m=120099888912383&w=2 We can do only cheap checking for sacked_out+lost_out > packets_out in mainline, and if that's true those warnings get printed but they won't necessarily tell the location of the bug because there might be considerable "latency" before that check triggers. On the other hand, this S+L debug patch verifies skb's ->sacked bitmaps against sacked/lost_out counters in multiple places per ACK and will catch the inconsistencies immediately at the site where they occurred (even if sacked_out + lost_out would still be below or equal to packets_out). -- i. ^ permalink raw reply [flat|nested] 20+ messages in thread
* Re: WARNING: at net/ipv4/tcp_input.c:2054 tcp_mark_head_lost() 2008-02-28 8:22 ` Ilpo Järvinen 2008-02-29 1:10 ` Andrew Morton @ 2008-03-02 12:20 ` Guillaume Chazarain 2008-03-02 12:38 ` Ilpo Järvinen 1 sibling, 1 reply; 20+ messages in thread From: Guillaume Chazarain @ 2008-03-02 12:20 UTC (permalink / raw) To: Ilpo Järvinen; +Cc: Giangiacomo Mariotti, LKML, Netdev, Andrew Morton On Thu, Feb 28, 2008 at 9:22 AM, Ilpo Järvinen <ilpo.jarvinen@helsinki.fi> wrote: > [PATCH] TCP debug S+L (for 2.6.25-rcs, incompatible with 2.6.24.y) Bittorrenting with this patch applied floods my dmesg. Here is a log dump: http://guichaz.free.fr/tcp-debug.log.bz2 (2.3M compressed, 113M uncompressed) It does not contain any "KERNEL: assertion (packets <= tp->packets_out) failed at" line, so I'm afraid it's just noise. Cheers. -- Guillaume ^ permalink raw reply [flat|nested] 20+ messages in thread
* Re: WARNING: at net/ipv4/tcp_input.c:2054 tcp_mark_head_lost() 2008-03-02 12:20 ` Guillaume Chazarain @ 2008-03-02 12:38 ` Ilpo Järvinen 2008-03-02 13:15 ` Guillaume Chazarain 0 siblings, 1 reply; 20+ messages in thread From: Ilpo Järvinen @ 2008-03-02 12:38 UTC (permalink / raw) To: Guillaume Chazarain; +Cc: Giangiacomo Mariotti, LKML, Netdev, Andrew Morton [-- Attachment #1: Type: TEXT/PLAIN, Size: 885 bytes --] On Sun, 2 Mar 2008, Guillaume Chazarain wrote: > On Thu, Feb 28, 2008 at 9:22 AM, Ilpo Järvinen <ilpo.jarvinen@helsinki.fi> wrote: > > [PATCH] TCP debug S+L (for 2.6.25-rcs, incompatible with 2.6.24.y) > > Bittorrenting with this patch applied floods my dmesg. Here is a log > dump: > > http://guichaz.free.fr/tcp-debug.log.bz2 (2.3M compressed, 113M > uncompressed) In future, please inline at least the first one of them, if not sure where to cut, too much won't hurt... :-) > It does not contain any "KERNEL: assertion (packets <= > tp->packets_out) failed at" line, so I'm afraid it's just noise. At least it catches one bug which could cause that assertion (it is much more rigid than the assertion and thus it catched it even though you won't see that assertion to ever trigger :-)). Could you next figure out what is at: [<c02e0f83>] tcp_ack+0x621/0xd2f -- i. ^ permalink raw reply [flat|nested] 20+ messages in thread
* Re: WARNING: at net/ipv4/tcp_input.c:2054 tcp_mark_head_lost() 2008-03-02 12:38 ` Ilpo Järvinen @ 2008-03-02 13:15 ` Guillaume Chazarain 2008-03-02 19:51 ` Ilpo Järvinen 0 siblings, 1 reply; 20+ messages in thread From: Guillaume Chazarain @ 2008-03-02 13:15 UTC (permalink / raw) To: Ilpo Järvinen; +Cc: Giangiacomo Mariotti, LKML, Netdev, Andrew Morton On Sun, Mar 2, 2008 at 1:38 PM, Ilpo Järvinen <ilpo.jarvinen@helsinki.fi> wrote: > In future, please inline at least the first one of them, if not sure > where to cut, too much won't hurt... :-) OK, will do. > > It does not contain any "KERNEL: assertion (packets <= > > tp->packets_out) failed at" line, so I'm afraid it's just noise. > > At least it catches one bug which could cause that assertion (it is much > more rigid than the assertion and thus it catched it even though you > won't see that assertion to ever trigger :-)). Great :-) > Could you next figure out what is at: > [<c02e0f83>] tcp_ack+0x621/0xd2f tcp_clean_rtx_queue() is automatically inlined into tcp_ack() by gcc. That's: tcp_ack(): /* See if we can take anything off of the retransmit queue. */ flag |= tcp_clean_rtx_queue(sk, prior_fackets); tcp_clean_rtx_queue(): tcp_verify_left_out(tp); <=========== Here if (skb && (TCP_SKB_CB(skb)->sacked & TCPCB_SACKED_ACKED)) flag |= FLAG_SACK_RENEGING; Thanks. -- Guillaume ^ permalink raw reply [flat|nested] 20+ messages in thread
* Re: WARNING: at net/ipv4/tcp_input.c:2054 tcp_mark_head_lost() 2008-03-02 13:15 ` Guillaume Chazarain @ 2008-03-02 19:51 ` Ilpo Järvinen 2008-03-03 8:32 ` Ilpo Järvinen 0 siblings, 1 reply; 20+ messages in thread From: Ilpo Järvinen @ 2008-03-02 19:51 UTC (permalink / raw) To: Guillaume Chazarain, Ray Lee, Chris Wedgwood Cc: Giangiacomo Mariotti, LKML, Netdev, Andrew Morton [-- Attachment #1: Type: TEXT/PLAIN, Size: 1011 bytes --] On Sun, 2 Mar 2008, Guillaume Chazarain wrote: >> On Sun, Mar 2, 2008 at 1:38 PM, Ilpo Järvinen <ilpo.jarvinen@helsinki.fi> wrote: >>> It does not contain any "KERNEL: assertion (packets <= >> > tp->packets_out) failed at" line, so I'm afraid it's just noise. Doh, you were right in this one... >> At least it catches one bug which could cause that assertion (it is much >> more rigid than the assertion and thus it catched it even though you >> won't see that assertion to ever trigger :-)). > > Great :-) ...I spoke too early, it was just that the verify call was placed into a place where the fackets_out is not yet reduced (I had too many version of that patch when I first did that and probably picked wrong one of them as a starting point, I'm sorry about that). I'll send an updated patch tomorrow for you and also correct it so that I don't need to ask things like this again (as long as one pastes couple of first occuring stacktraces): >>> Could you next figure out what is at: -- i. ^ permalink raw reply [flat|nested] 20+ messages in thread
* Re: WARNING: at net/ipv4/tcp_input.c:2054 tcp_mark_head_lost() 2008-03-02 19:51 ` Ilpo Järvinen @ 2008-03-03 8:32 ` Ilpo Järvinen 2008-03-03 13:40 ` Ilpo Järvinen 0 siblings, 1 reply; 20+ messages in thread From: Ilpo Järvinen @ 2008-03-03 8:32 UTC (permalink / raw) To: Guillaume Chazarain, Andrew Morton, Ray Lee, Chris Wedgwood Cc: Giangiacomo Mariotti, LKML, Netdev [-- Attachment #1: Type: TEXT/PLAIN, Size: 11516 bytes --] On Sun, 2 Mar 2008, Ilpo Järvinen wrote: > On Sun, 2 Mar 2008, Guillaume Chazarain wrote: > > >> On Sun, Mar 2, 2008 at 1:38 PM, Ilpo Järvinen <ilpo.jarvinen@helsinki.fi> wrote: > >>> It does not contain any "KERNEL: assertion (packets <= > >> > tp->packets_out) failed at" line, so I'm afraid it's just noise. > > Doh, you were right in this one... > > >> At least it catches one bug which could cause that assertion (it is much > >> more rigid than the assertion and thus it catched it even though you > >> won't see that assertion to ever trigger :-)). > > > > Great :-) > > ...I spoke too early, it was just that the verify call was placed into > a place where the fackets_out is not yet reduced (I had too many version > of that patch when I first did that and probably picked wrong one of > them as a starting point, I'm sorry about that). I'll send an updated > patch tomorrow for you and also correct it so that I don't need to ask > things like this again (as long as one pastes couple of first occuring > stacktraces): Here is the updated version... One of the stacktraces near the beginning (2nd or later) should now contain the line where the trap fired rather than having to figure that out from the stacktrace with eip address. Andrew, this is a minor update for it which avoids spurious triggers in tcp_clean_rtx_queue. -- i. [PATCH] TCP debug S+L (for 2.6.25-rcs, incompatible with 2.6.24.y), v1.1 Debugs sacked & lost skb inconstencies in TCP write queue & verifies fackets_out related variables. --- include/net/tcp.h | 10 +++- net/ipv4/tcp_input.c | 18 ++++++- net/ipv4/tcp_ipv4.c | 131 +++++++++++++++++++++++++++++++++++++++++++++++++ net/ipv4/tcp_output.c | 23 ++++++-- 4 files changed, 174 insertions(+), 8 deletions(-) diff --git a/include/net/tcp.h b/include/net/tcp.h index 7de4ea3..19192d8 100644 --- a/include/net/tcp.h +++ b/include/net/tcp.h @@ -272,6 +272,9 @@ DECLARE_SNMP_STAT(struct tcp_mib, tcp_statistics); #define TCP_ADD_STATS_BH(field, val) SNMP_ADD_STATS_BH(tcp_statistics, field, val) #define TCP_ADD_STATS_USER(field, val) SNMP_ADD_STATS_USER(tcp_statistics, field, val) +extern void tcp_print_queue(struct sock *sk); +extern int tcp_verify_wq(struct sock *sk); + extern void tcp_v4_err(struct sk_buff *skb, u32); extern void tcp_shutdown (struct sock *sk, int how); @@ -768,7 +771,12 @@ static inline __u32 tcp_current_ssthresh(const struct sock *sk) } /* Use define here intentionally to get WARN_ON location shown at the caller */ -#define tcp_verify_left_out(tp) WARN_ON(tcp_left_out(tp) > tp->packets_out) +#define tcp_verify_left_out(tp) \ + do {\ + int res; \ + res = tcp_verify_wq((struct sock *)tp); \ + WARN_ON(res || tcp_left_out(tp) > tp->packets_out); \ + } while(0) extern void tcp_enter_cwr(struct sock *sk, const int set_ssthresh); extern __u32 tcp_init_cwnd(struct tcp_sock *tp, struct dst_entry *dst); diff --git a/net/ipv4/tcp_input.c b/net/ipv4/tcp_input.c index 19c449f..bb0bdda 100644 --- a/net/ipv4/tcp_input.c +++ b/net/ipv4/tcp_input.c @@ -1426,8 +1426,10 @@ tcp_sacktag_write_queue(struct sock *sk, struct sk_buff *ack_skb, int first_sack_index; if (!tp->sacked_out) { - if (WARN_ON(tp->fackets_out)) + if (WARN_ON(tp->fackets_out)) { + tcp_verify_left_out(tp); tp->fackets_out = 0; + } tcp_highest_sack_reset(sk); } @@ -2136,6 +2138,8 @@ static void tcp_mark_head_lost(struct sock *sk, int packets, int fast_rexmit) struct sk_buff *skb; int cnt; + tcp_verify_left_out(tp); + BUG_TRAP(packets <= tp->packets_out); if (tp->lost_skb_hint) { skb = tp->lost_skb_hint; @@ -2501,6 +2505,8 @@ static void tcp_fastretrans_alert(struct sock *sk, int pkts_acked, int flag) (tcp_fackets_out(tp) > tp->reordering)); int fast_rexmit = 0; + tcp_verify_left_out(tp); + if (WARN_ON(!tp->packets_out && tp->sacked_out)) tp->sacked_out = 0; if (WARN_ON(!tp->sacked_out && tp->fackets_out)) @@ -2645,6 +2651,10 @@ static void tcp_fastretrans_alert(struct sock *sk, int pkts_acked, int flag) if (do_lost || (tcp_is_fack(tp) && tcp_head_timedout(sk))) tcp_update_scoreboard(sk, fast_rexmit); tcp_cwnd_down(sk, flag); + + WARN_ON(tcp_write_queue_head(sk) == NULL); + WARN_ON(!tp->packets_out); + tcp_xmit_retransmit_queue(sk); } @@ -2887,6 +2897,8 @@ static int tcp_clean_rtx_queue(struct sock *sk, int prior_fackets) } } + tcp_verify_left_out(tp); + #if FASTRETRANS_DEBUG > 0 BUG_TRAP((int)tp->sacked_out >= 0); BUG_TRAP((int)tp->lost_out >= 0); @@ -3175,6 +3187,8 @@ static int tcp_ack(struct sock *sk, struct sk_buff *skb, int flag) prior_fackets = tp->fackets_out; prior_in_flight = tcp_packets_in_flight(tp); + tcp_verify_left_out(tp); + if (!(flag & FLAG_SLOWPATH) && after(ack, prior_snd_una)) { /* Window is constant, pure forward advance. * No more checks are required. @@ -3237,6 +3251,8 @@ static int tcp_ack(struct sock *sk, struct sk_buff *skb, int flag) if ((flag & FLAG_FORWARD_PROGRESS) || !(flag & FLAG_NOT_DUP)) dst_confirm(sk->sk_dst_cache); + tcp_verify_left_out(tp); + return 1; no_queue: diff --git a/net/ipv4/tcp_ipv4.c b/net/ipv4/tcp_ipv4.c index 00156bf..1a59b3c 100644 --- a/net/ipv4/tcp_ipv4.c +++ b/net/ipv4/tcp_ipv4.c @@ -108,6 +108,137 @@ struct inet_hashinfo __cacheline_aligned tcp_hashinfo = { .lhash_wait = __WAIT_QUEUE_HEAD_INITIALIZER(tcp_hashinfo.lhash_wait), }; +void tcp_print_queue(struct sock *sk) +{ + struct tcp_sock *tp = tcp_sk(sk); + struct sk_buff *skb; + char s[50+1]; + char h[50+1]; + int idx = 0; + int i; + + i = 0; + tcp_for_write_queue(skb, sk) { + if (skb == tcp_send_head(sk)) + printk(KERN_ERR "head %u %p\n", i, skb); + else + printk(KERN_ERR "skb %u %p\n", i, skb); + i++; + } + + tcp_for_write_queue(skb, sk) { + if (skb == tcp_send_head(sk)) + break; + + for (i = 0; i < tcp_skb_pcount(skb); i++) { + if (TCP_SKB_CB(skb)->sacked & TCPCB_SACKED_ACKED) { + s[idx] = 'S'; + if (TCP_SKB_CB(skb)->sacked & TCPCB_LOST) + s[idx] = 'B'; + + } else if (TCP_SKB_CB(skb)->sacked & TCPCB_LOST) { + s[idx] = 'L'; + } else { + s[idx] = ' '; + } + if (s[idx] != ' ' && skb->len < tp->mss_cache) + s[idx] += 'a' - 'A'; + + if (i == 0) { + if (skb == tcp_highest_sack(sk)) + h[idx] = 'h'; + else + h[idx] = '+'; + } else { + h[idx] = '-'; + } + + if (++idx >= 50) { + s[idx] = 0; + h[idx] = 0; + printk(KERN_ERR "TCP wq(s) %s\n", s); + printk(KERN_ERR "TCP wq(h) %s\n", h); + idx = 0; + } + } + } + if (idx) { + s[idx] = '<'; + s[idx+1] = 0; + h[idx] = '<'; + h[idx+1] = 0; + printk(KERN_ERR "TCP wq(s) %s\n", s); + printk(KERN_ERR "TCP wq(h) %s\n", h); + } + printk(KERN_ERR "l%u s%u f%u p%u seq: su%u hs%u sn%u\n", + tp->lost_out, tp->sacked_out, tp->fackets_out, tp->packets_out, + tp->snd_una, tcp_highest_sack_seq(tp), tp->snd_nxt); +} + +int tcp_verify_wq(struct sock *sk) +{ + struct tcp_sock *tp = tcp_sk(sk); + u32 lost = 0; + u32 sacked = 0; + u32 packets = 0; + u32 fackets = 0; + int hs_valid = 0; + int inconsitent = 0; + struct sk_buff *skb; + + tcp_for_write_queue(skb, sk) { + if (skb == tcp_send_head(sk)) + break; + + if ((fackets == packets) && (skb == tp->highest_sack)) + hs_valid = 1; + + packets += tcp_skb_pcount(skb); + + if (TCP_SKB_CB(skb)->sacked & TCPCB_SACKED_ACKED) { + sacked += tcp_skb_pcount(skb); + if (TCP_SKB_CB(skb)->sacked & TCPCB_LOST) + printk(KERN_ERR "Sacked bitmap S+L: %u %u-%u/%u\n", + TCP_SKB_CB(skb)->sacked, + TCP_SKB_CB(skb)->end_seq - tp->snd_una, + TCP_SKB_CB(skb)->seq - tp->snd_una, + tp->snd_una); + fackets = packets; + hs_valid = 0; + } + if (TCP_SKB_CB(skb)->sacked & TCPCB_LOST) + lost += tcp_skb_pcount(skb); + } + + if ((fackets == packets) && (tp->highest_sack == tcp_send_head(sk))) + hs_valid = 1; + + if ((lost != tp->lost_out) || + (tcp_is_sack(tp) && (sacked != tp->sacked_out)) || + ((sacked || (tcp_is_sack(tp) && tp->sacked_out)) && !hs_valid) || + (packets != tp->packets_out) || + (fackets != tp->fackets_out) || + tcp_left_out(tp) > tp->packets_out) { + printk(KERN_ERR "P: %u L: %u vs %u S: %u vs %u F: %u vs %u w: %u-%u (%u)\n", + tp->packets_out, + lost, tp->lost_out, + sacked, tp->sacked_out, + fackets, tp->fackets_out, + tp->snd_una, tp->snd_nxt, + tp->rx_opt.sack_ok); + tcp_print_queue(sk); + inconsistent = 1; + } + + WARN_ON(lost != tp->lost_out); + WARN_ON(tcp_is_sack(tp) && (sacked != tp->sacked_out)); + WARN_ON(packets != tp->packets_out); + WARN_ON(fackets != tp->fackets_out); + WARN_ON(tcp_left_out(tp) > tp->packets_out); + + return inconsistent; +} + static inline __u32 tcp_v4_init_sequence(struct sk_buff *skb) { return secure_tcp_sequence_number(ip_hdr(skb)->daddr, diff --git a/net/ipv4/tcp_output.c b/net/ipv4/tcp_output.c index ed750f9..257de86 100644 --- a/net/ipv4/tcp_output.c +++ b/net/ipv4/tcp_output.c @@ -779,10 +779,9 @@ int tcp_fragment(struct sock *sk, struct sk_buff *skb, u32 len, tp->lost_out -= diff; /* Adjust Reno SACK estimate. */ - if (tcp_is_reno(tp) && diff > 0) { + if (tcp_is_reno(tp) && diff > 0) tcp_dec_pcount_approx_int(&tp->sacked_out, diff); - tcp_verify_left_out(tp); - } + tcp_adjust_fackets_out(sk, skb, diff); } @@ -790,6 +789,8 @@ int tcp_fragment(struct sock *sk, struct sk_buff *skb, u32 len, skb_header_release(buff); tcp_insert_write_queue_after(skb, buff, sk); + tcp_verify_left_out(tp); + return 0; } @@ -1463,6 +1464,7 @@ static int tcp_write_xmit(struct sock *sk, unsigned int mss_now, int nonagle) } else if (result > 0) { sent_pkts = 1; } + tcp_verify_left_out(tp); while ((skb = tcp_send_head(sk))) { unsigned int limit; @@ -1764,6 +1766,7 @@ static void tcp_retrans_try_collapse(struct sock *sk, struct sk_buff *skb, tcp_clear_retrans_hints_partial(tp); sk_wmem_free_skb(sk, next_skb); + tcp_verify_left_out(tp); } /* Do a simple retransmit without using the backoff mechanisms in @@ -1795,13 +1798,13 @@ void tcp_simple_retransmit(struct sock *sk) } } + tcp_verify_left_out(tp); + tcp_clear_all_retrans_hints(tp); if (!lost) return; - tcp_verify_left_out(tp); - /* Don't muck with the congestion window here. * Reason is that we do not increase amount of _data_ * in network, but units changed and effective @@ -1888,6 +1891,8 @@ int tcp_retransmit_skb(struct sock *sk, struct sk_buff *skb) tcp_init_nondata_skb(skb, TCP_SKB_CB(skb)->end_seq - 1, TCP_SKB_CB(skb)->flags); skb->ip_summed = CHECKSUM_NONE; + + tcp_verify_left_out(tp); } } @@ -1970,8 +1975,10 @@ void tcp_xmit_retransmit_queue(struct sock *sk) * packet to be MSS sized and all the * packet counting works out. */ - if (tcp_packets_in_flight(tp) >= tp->snd_cwnd) + if (tcp_packets_in_flight(tp) >= tp->snd_cwnd) { + tcp_verify_left_out(tp); return; + } if (sacked & TCPCB_LOST) { if (!(sacked & (TCPCB_SACKED_ACKED|TCPCB_SACKED_RETRANS))) { @@ -1997,6 +2004,8 @@ void tcp_xmit_retransmit_queue(struct sock *sk) } } + tcp_verify_left_out(tp); + /* OK, demanded retransmission is finished. */ /* Forward retransmissions are possible only during Recovery. */ @@ -2054,6 +2063,8 @@ void tcp_xmit_retransmit_queue(struct sock *sk) NET_INC_STATS_BH(LINUX_MIB_TCPFORWARDRETRANS); } + + tcp_verify_left_out(tp); } /* Send a fin. The caller locks the socket for us. This cannot be -- 1.5.2.2 ^ permalink raw reply related [flat|nested] 20+ messages in thread
* Re: WARNING: at net/ipv4/tcp_input.c:2054 tcp_mark_head_lost() 2008-03-03 8:32 ` Ilpo Järvinen @ 2008-03-03 13:40 ` Ilpo Järvinen 2008-03-03 13:53 ` [PATCH net-2.6] [TCP]: Must count fack_count also when skipping Ilpo Järvinen 0 siblings, 1 reply; 20+ messages in thread From: Ilpo Järvinen @ 2008-03-03 13:40 UTC (permalink / raw) To: Guillaume Chazarain, Andrew Morton, Ray Lee, Chris Wedgwood Cc: Giangiacomo Mariotti, LKML, Netdev [-- Attachment #1: Type: TEXT/PLAIN, Size: 11777 bytes --] On Mon, 3 Mar 2008, Ilpo Järvinen wrote: > On Sun, 2 Mar 2008, Ilpo Järvinen wrote: > > > On Sun, 2 Mar 2008, Guillaume Chazarain wrote: > > > > >> On Sun, Mar 2, 2008 at 1:38 PM, Ilpo Järvinen <ilpo.jarvinen@helsinki.fi> wrote: > > >>> It does not contain any "KERNEL: assertion (packets <= > > >> > tp->packets_out) failed at" line, so I'm afraid it's just noise. > > > > Doh, you were right in this one... I did some filtering among those and found out that some still point out bug (there might be indication of tcp_mark_head_lost inconsistency as well but it's nearly impossible to track with all the incorporated noise which is causing which). ...I'll post the patch separately right after this. > > ...I spoke too early, it was just that the verify call was placed into > > a place where the fackets_out is not yet reduced (I had too many version > > of that patch when I first did that and probably picked wrong one of > > them as a starting point, I'm sorry about that). I'll send an updated > > patch tomorrow for you and also correct it so that I don't need to ask > > things like this again (as long as one pastes couple of first occuring > > stacktraces): > > Here is the updated version... One of the stacktraces near the beginning > (2nd or later) should now contain the line where the trap fired rather > than having to figure that out from the stacktrace with eip address. > > Andrew, this is a minor update for it which avoids spurious triggers in > tcp_clean_rtx_queue. Argh, I thought I compile tested it by make net/ipv4/tcp_*.o but found typo there even after that... :-( -- i. [PATCH] TCP debug S+L (for 2.6.25-rcs, incompatible with 2.6.24.y), v1.2 Debugs sacked & lost skb inconstencies in TCP write queue & verifies fackets_out related variables. --- include/net/tcp.h | 10 +++- net/ipv4/tcp_input.c | 18 ++++++- net/ipv4/tcp_ipv4.c | 131 +++++++++++++++++++++++++++++++++++++++++++++++++ net/ipv4/tcp_output.c | 23 ++++++-- 4 files changed, 174 insertions(+), 8 deletions(-) diff --git a/include/net/tcp.h b/include/net/tcp.h index 7de4ea3..19192d8 100644 --- a/include/net/tcp.h +++ b/include/net/tcp.h @@ -272,6 +272,9 @@ DECLARE_SNMP_STAT(struct tcp_mib, tcp_statistics); #define TCP_ADD_STATS_BH(field, val) SNMP_ADD_STATS_BH(tcp_statistics, field, val) #define TCP_ADD_STATS_USER(field, val) SNMP_ADD_STATS_USER(tcp_statistics, field, val) +extern void tcp_print_queue(struct sock *sk); +extern int tcp_verify_wq(struct sock *sk); + extern void tcp_v4_err(struct sk_buff *skb, u32); extern void tcp_shutdown (struct sock *sk, int how); @@ -768,7 +771,12 @@ static inline __u32 tcp_current_ssthresh(const struct sock *sk) } /* Use define here intentionally to get WARN_ON location shown at the caller */ -#define tcp_verify_left_out(tp) WARN_ON(tcp_left_out(tp) > tp->packets_out) +#define tcp_verify_left_out(tp) \ + do {\ + int res; \ + res = tcp_verify_wq((struct sock *)tp); \ + WARN_ON(res || tcp_left_out(tp) > tp->packets_out); \ + } while(0) extern void tcp_enter_cwr(struct sock *sk, const int set_ssthresh); extern __u32 tcp_init_cwnd(struct tcp_sock *tp, struct dst_entry *dst); diff --git a/net/ipv4/tcp_input.c b/net/ipv4/tcp_input.c index 19c449f..bb0bdda 100644 --- a/net/ipv4/tcp_input.c +++ b/net/ipv4/tcp_input.c @@ -1426,8 +1426,10 @@ tcp_sacktag_write_queue(struct sock *sk, struct sk_buff *ack_skb, int first_sack_index; if (!tp->sacked_out) { - if (WARN_ON(tp->fackets_out)) + if (WARN_ON(tp->fackets_out)) { + tcp_verify_left_out(tp); tp->fackets_out = 0; + } tcp_highest_sack_reset(sk); } @@ -2136,6 +2138,8 @@ static void tcp_mark_head_lost(struct sock *sk, int packets, int fast_rexmit) struct sk_buff *skb; int cnt; + tcp_verify_left_out(tp); + BUG_TRAP(packets <= tp->packets_out); if (tp->lost_skb_hint) { skb = tp->lost_skb_hint; @@ -2501,6 +2505,8 @@ static void tcp_fastretrans_alert(struct sock *sk, int pkts_acked, int flag) (tcp_fackets_out(tp) > tp->reordering)); int fast_rexmit = 0; + tcp_verify_left_out(tp); + if (WARN_ON(!tp->packets_out && tp->sacked_out)) tp->sacked_out = 0; if (WARN_ON(!tp->sacked_out && tp->fackets_out)) @@ -2645,6 +2651,10 @@ static void tcp_fastretrans_alert(struct sock *sk, int pkts_acked, int flag) if (do_lost || (tcp_is_fack(tp) && tcp_head_timedout(sk))) tcp_update_scoreboard(sk, fast_rexmit); tcp_cwnd_down(sk, flag); + + WARN_ON(tcp_write_queue_head(sk) == NULL); + WARN_ON(!tp->packets_out); + tcp_xmit_retransmit_queue(sk); } @@ -2887,6 +2897,8 @@ static int tcp_clean_rtx_queue(struct sock *sk, int prior_fackets) } } + tcp_verify_left_out(tp); + #if FASTRETRANS_DEBUG > 0 BUG_TRAP((int)tp->sacked_out >= 0); BUG_TRAP((int)tp->lost_out >= 0); @@ -3175,6 +3187,8 @@ static int tcp_ack(struct sock *sk, struct sk_buff *skb, int flag) prior_fackets = tp->fackets_out; prior_in_flight = tcp_packets_in_flight(tp); + tcp_verify_left_out(tp); + if (!(flag & FLAG_SLOWPATH) && after(ack, prior_snd_una)) { /* Window is constant, pure forward advance. * No more checks are required. @@ -3237,6 +3251,8 @@ static int tcp_ack(struct sock *sk, struct sk_buff *skb, int flag) if ((flag & FLAG_FORWARD_PROGRESS) || !(flag & FLAG_NOT_DUP)) dst_confirm(sk->sk_dst_cache); + tcp_verify_left_out(tp); + return 1; no_queue: diff --git a/net/ipv4/tcp_ipv4.c b/net/ipv4/tcp_ipv4.c index 00156bf..d36c67c 100644 --- a/net/ipv4/tcp_ipv4.c +++ b/net/ipv4/tcp_ipv4.c @@ -108,6 +108,137 @@ struct inet_hashinfo __cacheline_aligned tcp_hashinfo = { .lhash_wait = __WAIT_QUEUE_HEAD_INITIALIZER(tcp_hashinfo.lhash_wait), }; +void tcp_print_queue(struct sock *sk) +{ + struct tcp_sock *tp = tcp_sk(sk); + struct sk_buff *skb; + char s[50+1]; + char h[50+1]; + int idx = 0; + int i; + + i = 0; + tcp_for_write_queue(skb, sk) { + if (skb == tcp_send_head(sk)) + printk(KERN_ERR "head %u %p\n", i, skb); + else + printk(KERN_ERR "skb %u %p\n", i, skb); + i++; + } + + tcp_for_write_queue(skb, sk) { + if (skb == tcp_send_head(sk)) + break; + + for (i = 0; i < tcp_skb_pcount(skb); i++) { + if (TCP_SKB_CB(skb)->sacked & TCPCB_SACKED_ACKED) { + s[idx] = 'S'; + if (TCP_SKB_CB(skb)->sacked & TCPCB_LOST) + s[idx] = 'B'; + + } else if (TCP_SKB_CB(skb)->sacked & TCPCB_LOST) { + s[idx] = 'L'; + } else { + s[idx] = ' '; + } + if (s[idx] != ' ' && skb->len < tp->mss_cache) + s[idx] += 'a' - 'A'; + + if (i == 0) { + if (skb == tcp_highest_sack(sk)) + h[idx] = 'h'; + else + h[idx] = '+'; + } else { + h[idx] = '-'; + } + + if (++idx >= 50) { + s[idx] = 0; + h[idx] = 0; + printk(KERN_ERR "TCP wq(s) %s\n", s); + printk(KERN_ERR "TCP wq(h) %s\n", h); + idx = 0; + } + } + } + if (idx) { + s[idx] = '<'; + s[idx+1] = 0; + h[idx] = '<'; + h[idx+1] = 0; + printk(KERN_ERR "TCP wq(s) %s\n", s); + printk(KERN_ERR "TCP wq(h) %s\n", h); + } + printk(KERN_ERR "l%u s%u f%u p%u seq: su%u hs%u sn%u\n", + tp->lost_out, tp->sacked_out, tp->fackets_out, tp->packets_out, + tp->snd_una, tcp_highest_sack_seq(tp), tp->snd_nxt); +} + +int tcp_verify_wq(struct sock *sk) +{ + struct tcp_sock *tp = tcp_sk(sk); + u32 lost = 0; + u32 sacked = 0; + u32 packets = 0; + u32 fackets = 0; + int hs_valid = 0; + int inconsistent = 0; + struct sk_buff *skb; + + tcp_for_write_queue(skb, sk) { + if (skb == tcp_send_head(sk)) + break; + + if ((fackets == packets) && (skb == tp->highest_sack)) + hs_valid = 1; + + packets += tcp_skb_pcount(skb); + + if (TCP_SKB_CB(skb)->sacked & TCPCB_SACKED_ACKED) { + sacked += tcp_skb_pcount(skb); + if (TCP_SKB_CB(skb)->sacked & TCPCB_LOST) + printk(KERN_ERR "Sacked bitmap S+L: %u %u-%u/%u\n", + TCP_SKB_CB(skb)->sacked, + TCP_SKB_CB(skb)->end_seq - tp->snd_una, + TCP_SKB_CB(skb)->seq - tp->snd_una, + tp->snd_una); + fackets = packets; + hs_valid = 0; + } + if (TCP_SKB_CB(skb)->sacked & TCPCB_LOST) + lost += tcp_skb_pcount(skb); + } + + if ((fackets == packets) && (tp->highest_sack == tcp_send_head(sk))) + hs_valid = 1; + + if ((lost != tp->lost_out) || + (tcp_is_sack(tp) && (sacked != tp->sacked_out)) || + ((sacked || (tcp_is_sack(tp) && tp->sacked_out)) && !hs_valid) || + (packets != tp->packets_out) || + (fackets != tp->fackets_out) || + tcp_left_out(tp) > tp->packets_out) { + printk(KERN_ERR "P: %u L: %u vs %u S: %u vs %u F: %u vs %u w: %u-%u (%u)\n", + tp->packets_out, + lost, tp->lost_out, + sacked, tp->sacked_out, + fackets, tp->fackets_out, + tp->snd_una, tp->snd_nxt, + tp->rx_opt.sack_ok); + tcp_print_queue(sk); + inconsistent = 1; + } + + WARN_ON(lost != tp->lost_out); + WARN_ON(tcp_is_sack(tp) && (sacked != tp->sacked_out)); + WARN_ON(packets != tp->packets_out); + WARN_ON(fackets != tp->fackets_out); + WARN_ON(tcp_left_out(tp) > tp->packets_out); + + return inconsistent; +} + static inline __u32 tcp_v4_init_sequence(struct sk_buff *skb) { return secure_tcp_sequence_number(ip_hdr(skb)->daddr, diff --git a/net/ipv4/tcp_output.c b/net/ipv4/tcp_output.c index ed750f9..257de86 100644 --- a/net/ipv4/tcp_output.c +++ b/net/ipv4/tcp_output.c @@ -779,10 +779,9 @@ int tcp_fragment(struct sock *sk, struct sk_buff *skb, u32 len, tp->lost_out -= diff; /* Adjust Reno SACK estimate. */ - if (tcp_is_reno(tp) && diff > 0) { + if (tcp_is_reno(tp) && diff > 0) tcp_dec_pcount_approx_int(&tp->sacked_out, diff); - tcp_verify_left_out(tp); - } + tcp_adjust_fackets_out(sk, skb, diff); } @@ -790,6 +789,8 @@ int tcp_fragment(struct sock *sk, struct sk_buff *skb, u32 len, skb_header_release(buff); tcp_insert_write_queue_after(skb, buff, sk); + tcp_verify_left_out(tp); + return 0; } @@ -1463,6 +1464,7 @@ static int tcp_write_xmit(struct sock *sk, unsigned int mss_now, int nonagle) } else if (result > 0) { sent_pkts = 1; } + tcp_verify_left_out(tp); while ((skb = tcp_send_head(sk))) { unsigned int limit; @@ -1764,6 +1766,7 @@ static void tcp_retrans_try_collapse(struct sock *sk, struct sk_buff *skb, tcp_clear_retrans_hints_partial(tp); sk_wmem_free_skb(sk, next_skb); + tcp_verify_left_out(tp); } /* Do a simple retransmit without using the backoff mechanisms in @@ -1795,13 +1798,13 @@ void tcp_simple_retransmit(struct sock *sk) } } + tcp_verify_left_out(tp); + tcp_clear_all_retrans_hints(tp); if (!lost) return; - tcp_verify_left_out(tp); - /* Don't muck with the congestion window here. * Reason is that we do not increase amount of _data_ * in network, but units changed and effective @@ -1888,6 +1891,8 @@ int tcp_retransmit_skb(struct sock *sk, struct sk_buff *skb) tcp_init_nondata_skb(skb, TCP_SKB_CB(skb)->end_seq - 1, TCP_SKB_CB(skb)->flags); skb->ip_summed = CHECKSUM_NONE; + + tcp_verify_left_out(tp); } } @@ -1970,8 +1975,10 @@ void tcp_xmit_retransmit_queue(struct sock *sk) * packet to be MSS sized and all the * packet counting works out. */ - if (tcp_packets_in_flight(tp) >= tp->snd_cwnd) + if (tcp_packets_in_flight(tp) >= tp->snd_cwnd) { + tcp_verify_left_out(tp); return; + } if (sacked & TCPCB_LOST) { if (!(sacked & (TCPCB_SACKED_ACKED|TCPCB_SACKED_RETRANS))) { @@ -1997,6 +2004,8 @@ void tcp_xmit_retransmit_queue(struct sock *sk) } } + tcp_verify_left_out(tp); + /* OK, demanded retransmission is finished. */ /* Forward retransmissions are possible only during Recovery. */ @@ -2054,6 +2063,8 @@ void tcp_xmit_retransmit_queue(struct sock *sk) NET_INC_STATS_BH(LINUX_MIB_TCPFORWARDRETRANS); } + + tcp_verify_left_out(tp); } /* Send a fin. The caller locks the socket for us. This cannot be -- 1.5.2.2 ^ permalink raw reply related [flat|nested] 20+ messages in thread
* [PATCH net-2.6] [TCP]: Must count fack_count also when skipping 2008-03-03 13:40 ` Ilpo Järvinen @ 2008-03-03 13:53 ` Ilpo Järvinen 2008-03-03 20:11 ` David Miller 2008-03-24 20:36 ` Frederik Himpe 0 siblings, 2 replies; 20+ messages in thread From: Ilpo Järvinen @ 2008-03-03 13:53 UTC (permalink / raw) To: David Miller Cc: Guillaume Chazarain, Andrew Morton, Ray Lee, Chris Wedgwood, Giangiacomo Mariotti, LKML, Netdev [-- Attachment #1: Type: TEXT/PLAIN, Size: 4225 bytes --] On Mon, 3 Mar 2008, Ilpo Järvinen wrote: > On Mon, 3 Mar 2008, Ilpo Järvinen wrote: > > > On Sun, 2 Mar 2008, Ilpo Järvinen wrote: > > > > > On Sun, 2 Mar 2008, Guillaume Chazarain wrote: > > > > > > >> On Sun, Mar 2, 2008 at 1:38 PM, Ilpo Järvinen <ilpo.jarvinen@helsinki.fi> wrote: > > > >>> It does not contain any "KERNEL: assertion (packets <= > > > >> > tp->packets_out) failed at" line, so I'm afraid it's just noise. > > > > > > Doh, you were right in this one... > > I did some filtering among those and found out that some still point out > bug (there might be indication of tcp_mark_head_lost inconsistency as > well but it's nearly impossible to track with all the incorporated noise > which is causing which). ...I'll post the patch separately right after > this. Dave, at least this is needed for TCP packet counter correctness, there could be other one hiding still because this only makes fackets_out too small (there could be second order effect though), while people are seeing a result of too large fackets_out in tcp_mark_head_lost. It's a bit shame that I didn't notice this when I verified time-seqno graphs after that sacktag rewrite (it mostly results just a substle difference in the slope). With this & the debug patch I didn't get anything into my logs but others might be more successful if there are other bugs still to solve that require more sophisticated network conditions to occur. -- i. [PATCH net-2.6] [TCP]: Must count fack_count also when skipping It makes fackets_out to grow too slowly compared with the real write queue. This shouldn't cause those BUG_TRAP(packets <= tp->packets_out) to trigger but how knows how such inconsistent fackets_out affects here and there around TCP when everything is nowadays assuming accurate fackets_out. So lets see if this silences them all. Reported by Guillaume Chazarain <guichaz@gmail.com>. Signed-off-by: Ilpo Järvinen <ilpo.jarvinen@helsinki.fi> --- net/ipv4/tcp_input.c | 14 +++++++++----- 1 files changed, 9 insertions(+), 5 deletions(-) diff --git a/net/ipv4/tcp_input.c b/net/ipv4/tcp_input.c index 19c449f..7facdb0 100644 --- a/net/ipv4/tcp_input.c +++ b/net/ipv4/tcp_input.c @@ -1367,7 +1367,7 @@ static struct sk_buff *tcp_sacktag_walk(struct sk_buff *skb, struct sock *sk, * a normal way */ static struct sk_buff *tcp_sacktag_skip(struct sk_buff *skb, struct sock *sk, - u32 skip_to_seq) + u32 skip_to_seq, int *fack_count) { tcp_for_write_queue_from(skb, sk) { if (skb == tcp_send_head(sk)) @@ -1375,6 +1375,8 @@ static struct sk_buff *tcp_sacktag_skip(struct sk_buff *skb, struct sock *sk, if (!before(TCP_SKB_CB(skb)->end_seq, skip_to_seq)) break; + + *fack_count += tcp_skb_pcount(skb); } return skb; } @@ -1390,7 +1392,7 @@ static struct sk_buff *tcp_maybe_skipping_dsack(struct sk_buff *skb, return skb; if (before(next_dup->start_seq, skip_to_seq)) { - skb = tcp_sacktag_skip(skb, sk, next_dup->start_seq); + skb = tcp_sacktag_skip(skb, sk, next_dup->start_seq, fack_count); tcp_sacktag_walk(skb, sk, NULL, next_dup->start_seq, next_dup->end_seq, 1, fack_count, reord, flag); @@ -1537,7 +1539,8 @@ tcp_sacktag_write_queue(struct sock *sk, struct sk_buff *ack_skb, /* Head todo? */ if (before(start_seq, cache->start_seq)) { - skb = tcp_sacktag_skip(skb, sk, start_seq); + skb = tcp_sacktag_skip(skb, sk, start_seq, + &fack_count); skb = tcp_sacktag_walk(skb, sk, next_dup, start_seq, cache->start_seq, @@ -1565,7 +1568,8 @@ tcp_sacktag_write_queue(struct sock *sk, struct sk_buff *ack_skb, goto walk; } - skb = tcp_sacktag_skip(skb, sk, cache->end_seq); + skb = tcp_sacktag_skip(skb, sk, cache->end_seq, + &fack_count); /* Check overlap against next cached too (past this one already) */ cache++; continue; @@ -1577,7 +1581,7 @@ tcp_sacktag_write_queue(struct sock *sk, struct sk_buff *ack_skb, break; fack_count = tp->fackets_out; } - skb = tcp_sacktag_skip(skb, sk, start_seq); + skb = tcp_sacktag_skip(skb, sk, start_seq, &fack_count); walk: skb = tcp_sacktag_walk(skb, sk, next_dup, start_seq, end_seq, -- 1.5.2.2 ^ permalink raw reply related [flat|nested] 20+ messages in thread
* Re: [PATCH net-2.6] [TCP]: Must count fack_count also when skipping 2008-03-03 13:53 ` [PATCH net-2.6] [TCP]: Must count fack_count also when skipping Ilpo Järvinen @ 2008-03-03 20:11 ` David Miller 2008-03-24 20:36 ` Frederik Himpe 1 sibling, 0 replies; 20+ messages in thread From: David Miller @ 2008-03-03 20:11 UTC (permalink / raw) To: ilpo.jarvinen Cc: guichaz, akpm, ray-lk, cw, giangiacomo_mariotti, linux-kernel, netdev From: "Ilpo_Järvinen" <ilpo.jarvinen@helsinki.fi> Date: Mon, 3 Mar 2008 15:53:12 +0200 (EET) > [PATCH net-2.6] [TCP]: Must count fack_count also when skipping > > It makes fackets_out to grow too slowly compared with the > real write queue. > > This shouldn't cause those BUG_TRAP(packets <= tp->packets_out) > to trigger but how knows how such inconsistent fackets_out > affects here and there around TCP when everything is nowadays > assuming accurate fackets_out. So lets see if this silences > them all. > > Reported by Guillaume Chazarain <guichaz@gmail.com>. > > Signed-off-by: Ilpo Järvinen <ilpo.jarvinen@helsinki.fi> Applied, thanks Ilpo. ^ permalink raw reply [flat|nested] 20+ messages in thread
* Re: [PATCH net-2.6] [TCP]: Must count fack_count also when skipping 2008-03-03 13:53 ` [PATCH net-2.6] [TCP]: Must count fack_count also when skipping Ilpo Järvinen 2008-03-03 20:11 ` David Miller @ 2008-03-24 20:36 ` Frederik Himpe 2008-03-24 21:41 ` David Miller 1 sibling, 1 reply; 20+ messages in thread From: Frederik Himpe @ 2008-03-24 20:36 UTC (permalink / raw) To: linux-kernel; +Cc: netdev On Mon, 03 Mar 2008 15:53:12 +0200, Ilpo Järvinen wrote: > [PATCH net-2.6] [TCP]: Must count fack_count also when skipping > > It makes fackets_out to grow too slowly compared with the real write > queue. > > This shouldn't cause those BUG_TRAP(packets <= tp->packets_out) to > trigger but how knows how such inconsistent fackets_out affects here and > there around TCP when everything is nowadays assuming accurate > fackets_out. So lets see if this silences them all. > > Reported by Guillaume Chazarain <guichaz@gmail.com>. Will this patch be applied to 2.6.24 stable? I think I have been hit by the same problem recently: WARNING: at net/ipv4/tcp_input.c:2054 tcp_mark_head_lost() Pid: 16959, comm: X Tainted: P 2.6.24.3-desktop-3mnb #1 Call Trace: <IRQ> [<ffffffff8045550c>] tcp_ack+0x180c/0x1d60 [<ffffffff80494259>] _read_lock_bh+0x9/0x20 [<ffffffff80458075>] tcp_rcv_state_process+0x3b5/0xd00 [<ffffffff8045f818>] tcp_v4_do_rcv+0xc8/0x3f0 [<ffffffff885601b3>] :nf_conntrack_ipv4:ipv4_confirm+0x33/0x60 [<ffffffff8043c316>] nf_iterate+0x66/0xc0 [<ffffffff804621b8>] tcp_v4_rcv+0x898/0xaf0 [<ffffffff80442ec3>] ip_local_deliver_finish+0xc3/0x250 [<ffffffff80442b64>] ip_rcv_finish+0x114/0x3b0 [<ffffffff80443365>] ip_rcv+0x205/0x2f0 [<ffffffff8041c45c>] netif_receive_skb+0x3ac/0x490 [<ffffffff88184509>] :forcedeth:nv_napi_poll+0xf9/0x850 [<ffffffff8041eaa8>] net_rx_action+0x128/0x230 [<ffffffff802412a5>] __do_softirq+0x75/0xe0 [<ffffffff8020d4fc>] call_softirq+0x1c/0x30 [<ffffffff8020f6c5>] do_softirq+0x35/0x90 [<ffffffff80241228>] irq_exit+0x88/0x90 [<ffffffff8020f910>] do_IRQ+0x80/0x100 [<ffffffff8020c881>] ret_from_intr+0x0/0xa <EOI> WARNING: at net/ipv4/tcp_input.c:2413 tcp_fastretrans_alert() Pid: 4053, comm: rsyslogd Tainted: P 2.6.24.3-desktop-3mnb #1 Call Trace: <IRQ> [<ffffffff80455a2d>] tcp_ack+0x1d2d/0x1d60 [<ffffffff80494259>] _read_lock_bh+0x9/0x20 [<ffffffff80458075>] tcp_rcv_state_process+0x3b5/0xd00 [<ffffffff8045f818>] tcp_v4_do_rcv+0xc8/0x3f0 [<ffffffff885601b3>] :nf_conntrack_ipv4:ipv4_confirm+0x33/0x60 [<ffffffff8043c316>] nf_iterate+0x66/0xc0 [<ffffffff804621b8>] tcp_v4_rcv+0x898/0xaf0 [<ffffffff80442ec3>] ip_local_deliver_finish+0xc3/0x250 [<ffffffff80442b64>] ip_rcv_finish+0x114/0x3b0 [<ffffffff80443365>] ip_rcv+0x205/0x2f0 [<ffffffff8041c45c>] netif_receive_skb+0x3ac/0x490 [<ffffffff88184509>] :forcedeth:nv_napi_poll+0xf9/0x850 [<ffffffff8041eaa8>] net_rx_action+0x128/0x230 [<ffffffff802412a5>] __do_softirq+0x75/0xe0 [<ffffffff8020d4fc>] call_softirq+0x1c/0x30 [<ffffffff8020f6c5>] do_softirq+0x35/0x90 [<ffffffff80241228>] irq_exit+0x88/0x90 [<ffffffff8020f910>] do_IRQ+0x80/0x100 [<ffffffff8020c881>] ret_from_intr+0x0/0xa <EOI> -- Frederik Himpe ^ permalink raw reply [flat|nested] 20+ messages in thread
* Re: [PATCH net-2.6] [TCP]: Must count fack_count also when skipping 2008-03-24 20:36 ` Frederik Himpe @ 2008-03-24 21:41 ` David Miller 2008-03-25 21:24 ` Ilpo Järvinen 0 siblings, 1 reply; 20+ messages in thread From: David Miller @ 2008-03-24 21:41 UTC (permalink / raw) To: fhimpe; +Cc: linux-kernel, netdev From: Frederik Himpe <fhimpe@telenet.be> Date: Mon, 24 Mar 2008 20:36:08 +0000 (UTC) > On Mon, 03 Mar 2008 15:53:12 +0200, Ilpo Järvinen > wrote: > > > [PATCH net-2.6] [TCP]: Must count fack_count also when skipping > > > > It makes fackets_out to grow too slowly compared with the real write > > queue. > > > > This shouldn't cause those BUG_TRAP(packets <= tp->packets_out) to > > trigger but how knows how such inconsistent fackets_out affects here and > > there around TCP when everything is nowadays assuming accurate > > fackets_out. So lets see if this silences them all. > > > > Reported by Guillaume Chazarain <guichaz@gmail.com>. > > Will this patch be applied to 2.6.24 stable? I think I have been hit by > the same problem recently: I'll push it to the -stable folks for their next release since people are actively hitting it. ^ permalink raw reply [flat|nested] 20+ messages in thread
* Re: [PATCH net-2.6] [TCP]: Must count fack_count also when skipping 2008-03-24 21:41 ` David Miller @ 2008-03-25 21:24 ` Ilpo Järvinen 2008-03-26 3:05 ` David Miller 0 siblings, 1 reply; 20+ messages in thread From: Ilpo Järvinen @ 2008-03-25 21:24 UTC (permalink / raw) To: David Miller; +Cc: fhimpe, LKML, Netdev [-- Attachment #1: Type: TEXT/PLAIN, Size: 2013 bytes --] On Mon, 24 Mar 2008, David Miller wrote: > From: Frederik Himpe <fhimpe@telenet.be> > Date: Mon, 24 Mar 2008 20:36:08 +0000 (UTC) > > > On Mon, 03 Mar 2008 15:53:12 +0200, Ilpo Järvinen > > wrote: > > > > > [PATCH net-2.6] [TCP]: Must count fack_count also when skipping > > > > > > It makes fackets_out to grow too slowly compared with the real write > > > queue. > > > > > > This shouldn't cause those BUG_TRAP(packets <= tp->packets_out) to > > > trigger but how knows how such inconsistent fackets_out affects here and > > > there around TCP when everything is nowadays assuming accurate > > > fackets_out. So lets see if this silences them all. > > > > > > Reported by Guillaume Chazarain <guichaz@gmail.com>. > > > > Will this patch be applied to 2.6.24 stable? I think I have been hit by > > the same problem recently: > > I'll push it to the -stable folks for their next release > since people are actively hitting it. Please don't, it's not the right fix, it fixed a bug that was introduced post 2.6.24 by this commit: commit 68f8353b480e5f2e136c38a511abdbb88eaa8ce2 Author: Ilpo Järvinen <ilpo.jarvinen@helsinki.fi> Date: Thu Nov 15 19:50:37 2007 -0800 [TCP]: Rewrite SACK block processing & sack_recv_cache use There's something else wrong with the 2.6.24.y. I already knew that and was therefore planning next to run extensive set of tests on 2.6.24ish kernel with some torrent mixed with some netem stimuli but haven't yet had time for that as I had to find and resolve an hw incompatibility issues between ddr2s and mobo before being a week away. I'll post an 2.6.24.y adapted TCP debug patch once I get that done for my tests (in case somebody else is interested in running with it besides me). Btw, it would have been polite to cc me as well (I suppose you just didn't notice that somebody dropped me in between :-)), not a big prob though as I found it out early anyway because I'm trying to catch up what has been reported against TCP during my week away. -- i. ^ permalink raw reply [flat|nested] 20+ messages in thread
* Re: [PATCH net-2.6] [TCP]: Must count fack_count also when skipping 2008-03-25 21:24 ` Ilpo Järvinen @ 2008-03-26 3:05 ` David Miller 0 siblings, 0 replies; 20+ messages in thread From: David Miller @ 2008-03-26 3:05 UTC (permalink / raw) To: ilpo.jarvinen; +Cc: fhimpe, linux-kernel, netdev From: "Ilpo_Järvinen" <ilpo.jarvinen@helsinki.fi> Date: Tue, 25 Mar 2008 23:24:55 +0200 (EET) > Please don't, it's not the right fix, it fixed a bug that was > introduced post 2.6.24 by this commit: Ok. > Btw, it would have been polite to cc me as well (I suppose you just didn't > notice that somebody dropped me in between :-)), not a big prob though as > I found it out early anyway because I'm trying to catch up what has been > reported against TCP during my week away. Sorry, my bad. ^ permalink raw reply [flat|nested] 20+ messages in thread
end of thread, other threads:[~2008-03-26 3:05 UTC | newest]
Thread overview: 20+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
[not found] <858077.97160.qm@web39709.mail.mud.yahoo.com>
2008-02-23 8:03 ` WARNING: at net/ipv4/tcp_input.c:2054 tcp_mark_head_lost() Andrew Morton
2008-02-27 9:29 ` Ilpo Järvinen
2008-02-27 18:56 ` Guillaume Chazarain
2008-02-27 19:29 ` Ilpo Järvinen
2008-02-28 8:22 ` Ilpo Järvinen
2008-02-29 1:10 ` Andrew Morton
2008-02-29 4:35 ` Bill Fink
2008-02-29 12:24 ` Ilpo Järvinen
2008-03-02 12:20 ` Guillaume Chazarain
2008-03-02 12:38 ` Ilpo Järvinen
2008-03-02 13:15 ` Guillaume Chazarain
2008-03-02 19:51 ` Ilpo Järvinen
2008-03-03 8:32 ` Ilpo Järvinen
2008-03-03 13:40 ` Ilpo Järvinen
2008-03-03 13:53 ` [PATCH net-2.6] [TCP]: Must count fack_count also when skipping Ilpo Järvinen
2008-03-03 20:11 ` David Miller
2008-03-24 20:36 ` Frederik Himpe
2008-03-24 21:41 ` David Miller
2008-03-25 21:24 ` Ilpo Järvinen
2008-03-26 3:05 ` David Miller
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).