From mboxrd@z Thu Jan 1 00:00:00 1970 From: Eric Dumazet Subject: Re: [2.6.34-rc1] CPU stalls when closing TCP sockets. Date: Tue, 09 Mar 2010 07:37:27 +0100 Message-ID: <1268116647.2819.64.camel@edumazet-laptop> References: <201003090319.o293J6WF026448@www262.sakura.ne.jp> Mime-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: QUOTED-PRINTABLE Cc: netdev@vger.kernel.org, linux-kernel@vger.kernel.org, "Paul E. McKenney" To: Tetsuo Handa Return-path: In-Reply-To: <201003090319.o293J6WF026448@www262.sakura.ne.jp> Sender: linux-kernel-owner@vger.kernel.org List-Id: netdev.vger.kernel.org Le mardi 09 mars 2010 =C3=A0 12:19 +0900, Tetsuo Handa a =C3=A9crit : > Hello. >=20 > Below program sometimes triggers CPU stall at (8). >=20 > ----- test program ----- > #include > #include > #include > #include > #include >=20 > int main(int argc, char *argv[]) > { > struct sockaddr_in saddr =3D { }; > struct sockaddr_in caddr =3D { }; > socklen_t size =3D sizeof(saddr); > int fd1 =3D socket(PF_INET, SOCK_STREAM, 0); > int fd2 =3D socket(PF_INET, SOCK_STREAM, 0); > int fd3 =3D EOF; > saddr.sin_family =3D AF_INET; > saddr.sin_addr.s_addr =3D htonl(INADDR_LOOPBACK); > saddr.sin_port =3D htons(0); > fprintf(stderr, "(1) Binding TCP 127.0.0.1 0 =3D "); > fprintf(stderr, "%d\n", bind(fd1, (struct sockaddr *) &saddr, > sizeof(saddr))); > fprintf(stderr, "(2) Getting server name =3D "); > fprintf(stderr, "%d\n", getsockname(fd1, (struct sockaddr *) &saddr, > &size)); > fprintf(stderr, "(3) Listening TCP 127.0.0.1 %d =3D ", > ntohs(saddr.sin_port)); > fprintf(stderr, "%d\n", listen(fd1, 5)); > fprintf(stderr, "(4) Connecting TCP 127.0.0.1 %d =3D ", > ntohs(saddr.sin_port)); > fprintf(stderr, "%d\n", connect(fd2, (struct sockaddr *) &saddr, > sizeof(saddr))); > fprintf(stderr, "(5) Getting client name =3D "); > fprintf(stderr, "%d\n", getsockname(fd2, (struct sockaddr *) &caddr, > &size)); > fprintf(stderr, "(6) Accepting TCP 127.0.0.1 %d =3D ", > ntohs(caddr.sin_port)); > fd3 =3D accept(fd1, (struct sockaddr *) &caddr, &size); > fprintf(stderr, "%d\n", fd3); > fprintf(stderr, "(7) Closing %d =3D ", fd3); > fprintf(stderr, "%d\n", close(fd3)); > fprintf(stderr, "(8) Closing %d =3D ", fd2); > fprintf(stderr, "%d\n", close(fd2)); > fprintf(stderr, "(9) Closing %d =3D ", fd1); > fprintf(stderr, "%d\n", close(fd1)); > return 0; > } > ----- test program ----- >=20 > [ 59.024080] INFO: RCU detected CPU 0 stall (t=3D2500 jiffies) > [ 59.024080] sending NMI to all CPUs: > [ 59.024080] NMI backtrace for cpu 0 > [ 59.024080] Modules linked in: ipv6 pcnet32 > [ 59.024080]=20 > [ 59.024080] Pid: 2720, comm: a.out Not tainted 2.6.34-rc1 #2 440BX= Desktop Reference Platform/VMware Virtual Platform > [ 59.024080] EIP: 0060:[] EFLAGS: 00000046 CPU: 0 > [ 59.024080] EIP is at default_send_IPI_mask_logical+0xa9/0x140 > [ 59.024080] EAX: fffff000 EBX: 01000000 ECX: 00000000 EDX: 00000c0= 0 > [ 59.024080] ESI: 00000c00 EDI: 00000046 EBP: c2400efc ESP: c2400ee= 0 > [ 59.024080] DS: 007b ES: 007b FS: 00d8 GS: 0033 SS: 0068 > [ 59.024080] Process a.out (pid: 2720, ti=3Dc2400000 task=3Ddebb60e= 0 task.ti=3Ddf324000) > [ 59.024080] Stack: > [ 59.024080] 0000000d be1bfc96 0000000d 00000002 00000000 c1464980= c1464980 c2400f08 > [ 59.024080] <0> c101e8d1 00000000 c2400f18 c101f1d7 c13c1569 c1464= 980 c2400f34 c108d637 > [ 59.024080] <0> c13d8620 00000000 000009c4 00000000 c1464980 c2400= f44 c108d6b8 c2545b00 > [ 59.024080] Call Trace: > [ 59.024080] [] ? default_send_IPI_all+0x81/0x90 > [ 59.024080] [] ? arch_trigger_all_cpu_backtrace+0x37/0x= 60 > [ 59.024080] [] ? print_cpu_stall+0x47/0x90 > [ 59.024080] [] ? check_cpu_stall+0x38/0x60 > [ 59.024080] [] ? __rcu_pending+0x25/0xb0 > [ 59.024080] [] ? rcu_pending+0x2e/0x70 > [ 59.024080] [] ? rcu_check_callbacks+0x1b/0xb0 > [ 59.024080] [] ? update_process_times+0x3d/0x70 > [ 59.024080] [] ? tick_periodic+0x2a/0x80 > [ 59.024080] [] ? tick_handle_periodic+0x1e/0x80 > [ 59.024080] [] ? timer_interrupt+0x23/0x50 > [ 59.024080] [] ? handle_IRQ_event+0x45/0x130 > [ 59.024080] [] ? handle_level_irq+0x88/0x100 > [ 59.024080] [] ? handle_level_irq+0x0/0x100 > [ 59.024080] =20 > [ 59.024080] [] ? do_IRQ+0x4a/0xc0 > [ 59.024080] [] ? common_interrupt+0x2e/0x34 > [ 59.024080] [] ? tcp_v4_rcv+0x154/0x670 > [ 59.024080] [] ? ip_local_deliver_finish+0xcb/0x1b0 > [ 59.024080] [] ? ip_local_deliver_finish+0x36/0x1b0 > [ 59.024080] [] ? ip_local_deliver+0x35/0x40 > [ 59.024080] [] ? ip_rcv_finish+0x10b/0x2d0 > [ 59.024080] [] ? ip_rcv+0x166/0x240 > [ 59.024080] [] ? netif_receive_skb+0x273/0x300 > [ 59.024080] [] ? netif_receive_skb+0x10d/0x300 > [ 59.024080] [] ? trace_hardirqs_on_caller+0xa6/0x160 > [ 59.024080] [] ? process_backlog+0x82/0xb0 > [ 59.024080] [] ? net_rx_action+0x11f/0x190 > [ 59.024080] [] ? __do_softirq+0x50/0x1c0 > [ 59.024080] [] ? __do_softirq+0xab/0x1c0 > [ 59.024080] [] ? dev_queue_xmit+0x209/0x370 > [ 59.024080] [] ? __do_softirq+0x0/0x1c0 > [ 59.024080] =20 > [ 59.024080] [] ? dev_queue_xmit+0x209/0x370 > [ 59.024080] [] ? local_bh_enable+0x8e/0xd0 > [ 59.024080] [] ? dev_queue_xmit+0x209/0x370 > [ 59.024080] [] ? dev_queue_xmit+0xee/0x370 > [ 59.024080] [] ? ip_finish_output+0x10f/0x270 > [ 59.024080] [] ? ip_output+0x51/0x60 > [ 59.024080] [] ? ip_local_out+0x1d/0x20 > [ 59.024080] [] ? ip_queue_xmit+0x20f/0x3e0 > [ 59.024080] [] ? sched_clock_local+0x15/0x170 > [ 59.024080] [] ? __change_page_attr+0x106/0x1b0 > [ 59.024080] [] ? __change_page_attr_set_clr+0x2f/0x70 > [ 59.024080] [] ? tcp_v4_send_check+0x52/0xe0 > [ 59.024080] [] ? tcp_transmit_skb+0x2d0/0x420 > [ 59.024080] [] ? poison_obj+0x2a/0x50 > [ 59.024080] [] ? __kmalloc_track_caller+0x185/0x1e0 > [ 59.024080] [] ? tcp_write_xmit+0x13f/0x290 > [ 59.024080] [] ? __tcp_push_pending_frames+0x36/0xf0 > [ 59.024080] [] ? tcp_send_fin+0x54/0xc0 > [ 59.024080] [] ? tcp_close+0x2f4/0x370 > [ 59.024080] [] ? trace_hardirqs_off+0xb/0x10 > [ 59.024080] [] ? inet_release+0x4e/0x60 > [ 59.024080] [] ? sock_release+0x66/0x80 > [ 59.024080] [] ? sock_close+0x17/0x30 > [ 59.024080] [] ? __fput+0x16e/0x1b0 > [ 59.024080] [] ? fput+0x1e/0x20 > [ 59.024080] [] ? filp_close+0x3f/0x70 > [ 59.024080] [] ? sys_close+0x68/0xb0 > [ 59.024080] [] ? syscall_call+0x7/0xb > [ 59.024080] Code: f6 c4 10 75 ed c1 e3 18 89 9a 10 c3 ff ff 8b 55 = f0 a1 8c 01 46 c1 09 f2 81 ce 00 04 00 00 83 7d f0 02 0f 44 d6 89 90 00= c3 ff ff <89> f8 c1 e8 09 83 f0 01 a8 01 74 0f 57 9d e8 64 69 05 00 83= c4=20 > [ 59.024080] Call Trace: > [ 59.024080] [] default_send_IPI_all+0x81/0x90 > [ 59.024080] [] arch_trigger_all_cpu_backtrace+0x37/0x60 > [ 59.024080] [] print_cpu_stall+0x47/0x90 > [ 59.024080] [] check_cpu_stall+0x38/0x60 > [ 59.024080] [] __rcu_pending+0x25/0xb0 > [ 59.024080] [] rcu_pending+0x2e/0x70 > [ 59.024080] [] rcu_check_callbacks+0x1b/0xb0 > [ 59.024080] [] update_process_times+0x3d/0x70 > [ 59.024080] [] tick_periodic+0x2a/0x80 > [ 59.024080] [] tick_handle_periodic+0x1e/0x80 > [ 59.024080] [] timer_interrupt+0x23/0x50 > [ 59.024080] [] handle_IRQ_event+0x45/0x130 > [ 59.024080] [] handle_level_irq+0x88/0x100 > [ 59.024080] [] ? handle_level_irq+0x0/0x100 > [ 59.024080] [] ? do_IRQ+0x4a/0xc0 > [ 59.024080] [] ? common_interrupt+0x2e/0x34 > [ 59.024080] [] ? tcp_v4_rcv+0x154/0x670 > [ 59.024080] [] ? ip_local_deliver_finish+0xcb/0x1b0 > [ 59.024080] [] ? ip_local_deliver_finish+0x36/0x1b0 > [ 59.024080] [] ? ip_local_deliver+0x35/0x40 > [ 59.024080] [] ? ip_rcv_finish+0x10b/0x2d0 > [ 59.024080] [] ? ip_rcv+0x166/0x240 > [ 59.024080] [] ? netif_receive_skb+0x273/0x300 > [ 59.024080] [] ? netif_receive_skb+0x10d/0x300 > [ 59.024080] [] ? trace_hardirqs_on_caller+0xa6/0x160 > [ 59.024080] [] ? process_backlog+0x82/0xb0 > [ 59.024080] [] ? net_rx_action+0x11f/0x190 > [ 59.024080] [] ? __do_softirq+0x50/0x1c0 > [ 59.024080] [] ? __do_softirq+0xab/0x1c0 > [ 59.024080] [] ? dev_queue_xmit+0x209/0x370 > [ 59.024080] [] ? __do_softirq+0x0/0x1c0 > [ 59.024080] [] ? dev_queue_xmit+0x209/0x370 > [ 59.024080] [] ? local_bh_enable+0x8e/0xd0 > [ 59.024080] [] ? dev_queue_xmit+0x209/0x370 > [ 59.024080] [] ? dev_queue_xmit+0xee/0x370 > [ 59.024080] [] ? ip_finish_output+0x10f/0x270 > [ 59.024080] [] ? ip_output+0x51/0x60 > [ 59.024080] [] ? ip_local_out+0x1d/0x20 > [ 59.024080] [] ? ip_queue_xmit+0x20f/0x3e0 > [ 59.024080] [] ? sched_clock_local+0x15/0x170 > [ 59.024080] [] ? __change_page_attr+0x106/0x1b0 > [ 59.024080] [] ? __change_page_attr_set_clr+0x2f/0x70 > [ 59.024080] [] ? tcp_v4_send_check+0x52/0xe0 > [ 59.024080] [] ? tcp_transmit_skb+0x2d0/0x420 > [ 59.024080] [] ? poison_obj+0x2a/0x50 > [ 59.024080] [] ? __kmalloc_track_caller+0x185/0x1e0 > [ 59.024080] [] ? tcp_write_xmit+0x13f/0x290 > [ 59.024080] [] ? __tcp_push_pending_frames+0x36/0xf0 > [ 59.024080] [] ? tcp_send_fin+0x54/0xc0 > [ 59.024080] [] ? tcp_close+0x2f4/0x370 > [ 59.024080] [] ? trace_hardirqs_off+0xb/0x10 > [ 59.024080] [] ? inet_release+0x4e/0x60 > [ 59.024080] [] ? sock_release+0x66/0x80 > [ 59.024080] [] ? sock_close+0x17/0x30 > [ 59.024080] [] ? __fput+0x16e/0x1b0 > [ 59.024080] [] ? fput+0x1e/0x20 > [ 59.024080] [] ? filp_close+0x3f/0x70 > [ 59.024080] [] ? sys_close+0x68/0xb0 > [ 59.024080] [] ? syscall_call+0x7/0xb > [ 59.024080] Pid: 2720, comm: a.out Not tainted 2.6.34-rc1 #2 > [ 59.024080] Call Trace: > [ 59.024080] [] ? show_regs+0x27/0x30 > [ 59.024080] [] nmi_watchdog_tick+0x189/0x240 > [ 59.024080] [] default_do_nmi+0x5f/0x180 > [ 59.024080] [] do_nmi+0x89/0xa0 > [ 59.024080] [] nmi_stack_correct+0x28/0x2d > [ 59.024080] [] ? default_send_IPI_mask_logical+0xa9/0x1= 40 > [ 59.024080] [] default_send_IPI_all+0x81/0x90 > [ 59.024080] [] arch_trigger_all_cpu_backtrace+0x37/0x60 > [ 59.024080] [] print_cpu_stall+0x47/0x90 > [ 59.024080] [] check_cpu_stall+0x38/0x60 > [ 59.024080] [] __rcu_pending+0x25/0xb0 > [ 59.024080] [] rcu_pending+0x2e/0x70 > [ 59.024080] [] rcu_check_callbacks+0x1b/0xb0 > [ 59.024080] [] update_process_times+0x3d/0x70 > [ 59.024080] [] tick_periodic+0x2a/0x80 > [ 59.024080] [] tick_handle_periodic+0x1e/0x80 > [ 59.024080] [] timer_interrupt+0x23/0x50 > [ 59.024080] [] handle_IRQ_event+0x45/0x130 > [ 59.024080] [] handle_level_irq+0x88/0x100 > [ 59.024080] [] ? handle_level_irq+0x0/0x100 > [ 59.024080] [] ? do_IRQ+0x4a/0xc0 > [ 59.024080] [] ? common_interrupt+0x2e/0x34 > [ 59.024080] [] ? tcp_v4_rcv+0x154/0x670 > [ 59.024080] [] ? ip_local_deliver_finish+0xcb/0x1b0 > [ 59.024080] [] ? ip_local_deliver_finish+0x36/0x1b0 > [ 59.024080] [] ? ip_local_deliver+0x35/0x40 > [ 59.024080] [] ? ip_rcv_finish+0x10b/0x2d0 > [ 59.024080] [] ? ip_rcv+0x166/0x240 > [ 59.024080] [] ? netif_receive_skb+0x273/0x300 > [ 59.024080] [] ? netif_receive_skb+0x10d/0x300 > [ 59.024080] [] ? trace_hardirqs_on_caller+0xa6/0x160 > [ 59.024080] [] ? process_backlog+0x82/0xb0 > [ 59.024080] [] ? net_rx_action+0x11f/0x190 > [ 59.024080] [] ? __do_softirq+0x50/0x1c0 > [ 59.024080] [] ? __do_softirq+0xab/0x1c0 > [ 59.024080] [] ? dev_queue_xmit+0x209/0x370 > [ 59.024080] [] ? __do_softirq+0x0/0x1c0 > [ 59.024080] [] ? dev_queue_xmit+0x209/0x370 > [ 59.024080] [] ? local_bh_enable+0x8e/0xd0 > [ 59.024080] [] ? dev_queue_xmit+0x209/0x370 > [ 59.024080] [] ? dev_queue_xmit+0xee/0x370 > [ 59.024080] [] ? ip_finish_output+0x10f/0x270 > [ 59.024080] [] ? ip_output+0x51/0x60 > [ 59.024080] [] ? ip_local_out+0x1d/0x20 > [ 59.024080] [] ? ip_queue_xmit+0x20f/0x3e0 > [ 59.024080] [] ? sched_clock_local+0x15/0x170 > [ 59.024080] [] ? __change_page_attr+0x106/0x1b0 > [ 59.024080] [] ? __change_page_attr_set_clr+0x2f/0x70 > [ 59.024080] [] ? tcp_v4_send_check+0x52/0xe0 > [ 59.024080] [] ? tcp_transmit_skb+0x2d0/0x420 > [ 59.024080] [] ? poison_obj+0x2a/0x50 > [ 59.024080] [] ? __kmalloc_track_caller+0x185/0x1e0 > [ 59.024080] [] ? tcp_write_xmit+0x13f/0x290 > [ 59.024080] [] ? __tcp_push_pending_frames+0x36/0xf0 > [ 59.024080] [] ? tcp_send_fin+0x54/0xc0 > [ 59.024080] [] ? tcp_close+0x2f4/0x370 > [ 59.024080] [] ? trace_hardirqs_off+0xb/0x10 > [ 59.024080] [] ? inet_release+0x4e/0x60 > [ 59.024080] [] ? sock_release+0x66/0x80 > [ 59.024080] [] ? sock_close+0x17/0x30 > [ 59.024080] [] ? __fput+0x16e/0x1b0 > [ 59.024080] [] ? fput+0x1e/0x20 > [ 59.024080] [] ? filp_close+0x3f/0x70 > [ 59.024080] [] ? sys_close+0x68/0xb0 > [ 59.024080] [] ? syscall_call+0x7/0xb >=20 > Full log is at http://I-love.SAKURA.ne.jp/tmp/dmesg-2.6.34-rc1.txt > Config is at http://I-love.SAKURA.ne.jp/tmp/config-2.6.34-rc1 Thanks for the report and program. Nothing comes to my mind, I'll try to reproduce this here. Is 2.6.33 OK ? Thanks