We need help from someone who knows the network code. I have tried to give all the relevant information below. The machine that last failed can still be examined with kgdb to answer any further questions.
We are working with a 2.4.17 kernel with all the latest preempt patches as well as the high-res-timres patch (which, by the way has the proposed TIMER_BH conversion to softirq code). Other patches are applied but, when removed, do not affect the below described behavior. The system is an SMP (2) processor: <4>CPU0: Intel(R) Pentium(R) III CPU family 1266MHz stepping 01
A break point placed in deliver_to_old_ones() is never hit.
Failure rate under heavy network stress (4 machines each measuring network performance with all 4 machines in the test) occurs very seldom. The last failure took 32 hours, the prior one 22 hours.
Failure appears to occur because a call is made to a bogus address that is pulled from an skb.
Here is a back trace of the latest failure:
Program received signal SIGEMT, Emulation trap.
0x00b24d18 in ?? () at af_packet.c:1891
(gdb) bt
#0 0x00b24d18 in ?? () at af_packet.c:1891
#1 0xc0267751 in tcp_v4_destroy_sock (sk=0xc7164260)
at /usr/src/linux-2.4.17-CLT/include/net/tcp.h:1673
#2 0xc02566f1 in tcp_destroy_sock (sk=0xc7164260) at tcp.c:1800
#3 0xc025731a in tcp_close (sk=0xc7164260, timeout=0) at tcp.c:1971
#4 0xc0274f67 in inet_release (sock=0xc2c94160) at af_inet.c:465
#5 0xc02304a2 in sock_release (sock=0xc2c94160) at socket.c:489
#6 0xc0230a50 in sock_close (inode=0xc2c94040, filp=0xc51297e0)
at socket.c:724
#7 0xc014d833 in fput (file=0xc51297e0) at file_table.c:113
#8 0xc014bfe3 in filp_close (filp=0xc51297e0, id=0xc2eb6d60) at open.c:838
#9 0xc014c0b2 in sys_close (fd=4) at open.c:862
#10 0xc010782b in system_call () at af_packet.c:1891
#11 0x40043507 in ?? () at af_packet.c:1891
(
kgdb caught this in:
0xc0119b3d is in do_page_fault (fault.c:329).
324 * terminate things with extreme prejudice.
325 */
326 #ifdef CONFIG_KGDB
327 if (!user_mode(regs)){
328 kgdb_handle_exception(14,SIGBUS, error_code, regs);
329 return;
330 }
331 #endif
332
333 bust_spinlocks(1);
(
In both failures we found this in the log buffer just prior to the failure:
<5>\n<4>KERNEL: assertion ((int)tcp_packets_in_flight(tp) >= 0) failed at tcp_input.c(956):tcp_sacktag_write_queue\n
On the assumption that preemption is the root cause of this problem we have instrumented the preemption code to keep track of the last 100 preemptions. What follows is an edited log
of these preemptions. Each entry consists of two words of time (sec, usec) followed by the
address (hex and symbolic) and the pid of the process. Preemptions clearly unrelated to the network code have been removed. Most of these were in idle or sched_yield.
0xc0368e60 <preempt_log>: 0x3d101941 0xc9868 0xc025f4bb <tcp_transmit_skb+747> 0x15aa
0xc0368e80 <preempt_log+32>: 0x3d101941 0xec247 0xc025d821 <tcp_copy_to_iovec+129> 0x15aa
0xc0368ea0 <preempt_log+64>: 0x3d101942 0xc1f6 0xc0167ee0 <update_atime> 0x15ae
0xc0368ec0 <preempt_log+96>: 0x3d101942 0x24440 0xc025d821 <tcp_copy_to_iovec+129> 0x15aa
0xc0368ee0 <preempt_log+128>: 0x3d101942 0x26eae 0xc025d821 <tcp_copy_to_iovec+129> 0x15a9
0xc0368f00 <preempt_log+160>: 0x3d101942 0x2a4b4 0xc025d821 <tcp_copy_to_iovec+129> 0x15aa
0xc0368f20 <preempt_log+192>: 0x3d101942 0x2c74a 0xc02558b1 <tcp_prequeue_process+305> 0x15aa
0xc0368f40 <preempt_log+224>: 0x3d101942 0x2d5b6 0xc0255741 <tcp_data_wait+705> 0x15aa
0xc0368f60 <preempt_log+256>: 0x3d101942 0x2e634 0xc02558b1 <tcp_prequeue_process+305> 0x15a9
0xc0368f80 <preempt_log+288>: 0x3d101942 0x2fcaa 0xc024db81 <ip_output+401> 0x15aa
0xc0368fc0 <preempt_log+352>: 0x3d101942 0x30c4f 0xc02558b1 <tcp_prequeue_process+305> 0x15a6
0xc0368fe0 <preempt_log+384>: 0x3d101942 0x33603 0xc02558b1 <tcp_prequeue_process+305> 0x15a6
0xc0369000 <preempt_log+416>: 0x3d101942 0xc5137 0xc011d1ec <remove_wait_queue+156> 0x15a8
0xc0369060 <preempt_log+512>: 0x3d101944 0x6f2e4 0xc025561b <tcp_data_wait+411> 0x15a8
0xc0369120 <preempt_log+704>: 0x3d101948 0xae22f 0xc024dc28 <ip_queue_xmit+24> 0x15b2
0xc0369140 <preempt_log+736>: 0x3d101949 0xbe01 0xc02558b1 <tcp_prequeue_process+305> 0x15b2
0xc03691a0 <preempt_log+832>: 0x3d10194b 0xbd567 0xc025d821 <tcp_copy_to_iovec+129> 0x15b3
0xc0369250 <preempt_log+1008>: 0x3d10194b 0xbde39 0xc01054df <default_idle+47> 0x0
Each of these is pinned to source below:
(gdb)
(gdb)l* l* tcp_transmit_skb+747
0xc01f4a83 is in tcp_transmit_skb (/usr/src/cvs/hhl-kernel-cambell/linux_test/include/net/tcp.h:1422).
1417 TCPOLEN_TIMESTAMP);
1418 *ptr++ = htonl(tstamp);
1419 *ptr++ = htonl(tp->ts_recent);
1420 }
1421 if (tp->eff_sacks) {
1422 struct tcp_sack_block *sp = tp->dsack ? tp->duplicate_sack : tp->selective_acks;
1423 int this_sack;
1424
1425 *ptr++ = __constant_htonl((TCPOPT_NOP << 24) |
1426 (TCPOPT_NOP << 16) |
(gdb)l * tcp_copy_to_iovec+129
0xc01f2eed is in tcp_copy_to_iovec (tcp_input.c:3157).
3152 int chunk = skb->len - hlen;
3153 int err;
3154
3155 local_bh_enable();
3156 if (skb->ip_summed==CHECKSUM_UNNECESSARY)
3157 err = skb_copy_datagram_iovec(skb, hlen, tp->ucopy.iov, chunk);
3158 else
3159 err = skb_copy_and_csum_datagram_iovec(skb, hlen, tp->ucopy.iov);
3160
3161 if (!err) {
(gdb) l *tcp_prequeue_process+305
0xc01ebba5 is in tcp_recvmsg (tcp.c:1400).
1395 int err;
1396 int target; /* Read at least this many bytes */
1397 long timeo;
1398 struct task_struct *user_recv = NULL;
1399
1400 lock_sock(sk);
1401
1402 TCP_CHECK_TIMER(sk);
1403
1404 err = -ENOTCONN;
(gdb) l* tcp_data_wait+705
0xc01ebb49 is in tcp_prequeue_process (tcp.c:1376).
1371 while ((skb = __skb_dequeue(&tp->ucopy.prequeue)) != NULL)
1372 sk->backlog_rcv(sk, skb);
1373 local_bh_enable();
1374
1375 /* Clear memory counter. */
1376 tp->ucopy.memory = 0;
1377 }
1378
1379 /*
1380 * This routine copies from a sock struct into the user buffer.
(gdb) l *tcp_data_wait+411
0xc01eba23 is in tcp_data_wait (tcp.c:1354).
1349 release_sock(sk);
1350
1351 if (skb_queue_empty(&sk->receive_queue))
1352 timeo = schedule_timeout(timeo);
1353
1354 lock_sock(sk);
1355 clear_bit(SOCK_ASYNC_WAITDATA, &sk->socket->flags);
1356
1357 remove_wait_queue(sk->sleep, &wait);
1358 __set_current_state(TASK_RUNNING);
(gdb) (gdb) l *ip_queue_xmit+24
0xc024dc28 is in ip_queue_xmit (ip_output.c:351).
346 struct iphdr *iph;
347
348 /* Skip all of this if the packet is already routed,
349 * f.e. by something like SCTP.
350 */
351 rt = (struct rtable *) skb->dst;
352 if (rt != NULL)
353 goto packet_routed;
354
355 /* Make sure we can route this packet. */
(gdb)
(gdb) l * ip_output+401
0xc01e55d9 is in ip_queue_xmit (ip_output.c:344).
339 }
340
341 int ip_queue_xmit(struct sk_buff *skb)
342 {
343 struct sock *sk = skb->sk;
344 struct ip_options *opt = sk->protinfo.af_inet.opt;
345 struct rtable *rt;
346 struct iphdr *iph;
347
348 /* Skip all of this if the packet is already routed,
Any help would be greatly appreciated. We also can probe the system to answer any further questions. As said above, we are assuming this is related to preemption, however, that assumption may be bad.
Thanks
--
George Anzinger george@mvista.com
High-res-timers: http://sourceforge.net/projects/high-res-timers/
Real time sched: http://sourceforge.net/projects/rtsched/
Preemption patch: http://www.kernel.org/pub/linux/kernel/people/rml
-
: send the line "unsubscribe linux-net" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
