Message-ID: <20171023095634.lednbqrxtbuooqcx@inn>
Date:   Mon, 23 Oct 2017 17:56:34 +0800
From:   kernel test robot <fengguang.wu@...el.com>
To:     Eric Dumazet <eric.dumazet@...il.com>
Cc:     David Miller <davem@...emloft.net>,
        netdev <netdev@...r.kernel.org>, lkp@...org
Subject: [tcp/dccp]  81e5391ca7: WARNING:suspicious_RCU_usage

FYI, we noticed the following commit (built with gcc-6):

commit: 81e5391ca7f31181de672cc96d83e8ba3b7ac567 ("tcp/dccp: fix lockdep splat in inet_csk_route_req()")
url: https://github.com/0day-ci/linux/commits/Eric-Dumazet/tcp-dccp-fix-lockdep-splat-in-inet_csk_route_req/20171023-040135


in testcase: netpipe
with following parameters:

	test: tcp
	cluster: cs-localhost

test-description: NetPIPE is a protocol independent performance tool that encapsulates the best of ttcp and netperf and visually represents the network performance under a variety of conditions.
test-url: http://bitspjoule.org/netpipe/


on test machine: qemu-system-x86_64 -enable-kvm -cpu host -smp 2 -m 4G

caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):


+------------------------------------------------------------------------------+------------+------------+
|                                                                              | 8d5f4b0717 | 81e5391ca7 |
+------------------------------------------------------------------------------+------------+------------+
| boot_successes                                                               | 2          | 2          |
| boot_failures                                                                | 0          | 4          |
| WARNING:suspicious_RCU_usage                                                 | 0          | 4          |
| net/ipv4/inet_connection_sock.c:#suspicious_rcu_dereference_protected()usage | 0          | 4          |
+------------------------------------------------------------------------------+------------+------------+



[   49.794113] WARNING: suspicious RCU usage
[   49.795888] 4.14.0-rc4-00174-g81e5391 #8 Not tainted
[   49.798216] -----------------------------
[   49.799980] net/ipv4/inet_connection_sock.c:547 suspicious rcu_dereference_protected() usage!
[   49.804411] 
[   49.804411] other info that might help us debug this:
[   49.804411] 
[   49.808744] 
[   49.808744] rcu_scheduler_active = 2, debug_locks = 1
[   49.811852] 4 locks held by NPtcp/7896:
[   49.813595]  #0:  (sk_lock-AF_INET){+.+.}, at: [<ffffffffa1cd4b36>] inet_stream_connect+0x24/0x4d
[   49.818092]  #1:  (rcu_read_lock){....}, at: [<ffffffffa1ca2f11>] ip_queue_xmit+0x5/0x48e
[   49.821892]  #2:  (rcu_read_lock){....}, at: [<ffffffffa1c3643d>] process_backlog+0x7e/0x216
[   49.825761]  #3:  (rcu_read_lock){....}, at: [<ffffffffa1c9dc85>] ip_local_deliver_finish+0x2d/0x2e7
[   49.830024] 
[   49.830024] stack backtrace:
[   49.832859] CPU: 0 PID: 7896 Comm: NPtcp Not tainted 4.14.0-rc4-00174-g81e5391 #8
[   49.836178] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[   49.840122] Call Trace:
[   49.841518]  <IRQ>
[   49.842936]  dump_stack+0x86/0xc0
[   49.844590]  lockdep_rcu_suspicious+0xea/0xf3
[   49.846487]  inet_csk_route_req+0x53/0x14d
[   49.848334]  tcp_v4_route_req+0xe/0x10
[   49.850174]  tcp_conn_request+0x31c/0x6a0
[   49.851992]  ? __lock_acquire+0x614/0x822
[   49.854015]  tcp_v4_conn_request+0x5a/0x79
[   49.855957]  ? tcp_v4_conn_request+0x5a/0x79
[   49.858052]  tcp_rcv_state_process+0x98/0xdcc
[   49.859990]  ? sk_filter_trim_cap+0x2f6/0x307
[   49.862085]  tcp_v4_do_rcv+0xfc/0x145
[   49.864055]  ? tcp_v4_do_rcv+0xfc/0x145
[   49.866173]  tcp_v4_rcv+0x5ab/0xaf9
[   49.868029]  ip_local_deliver_finish+0x1af/0x2e7
[   49.870064]  ip_local_deliver+0x1b2/0x1c5
[   49.871775]  ? inet_del_offload+0x45/0x45
[   49.873916]  ip_rcv_finish+0x3f7/0x471
[   49.875476]  ip_rcv+0x3f1/0x42f
[   49.876991]  ? ip_local_deliver_finish+0x2e7/0x2e7
[   49.878791]  __netif_receive_skb_core+0x6d3/0x950
[   49.880701]  ? process_backlog+0x7e/0x216
[   49.882589]  __netif_receive_skb+0x1d/0x5e
[   49.884122]  process_backlog+0x10c/0x216
[   49.885812]  net_rx_action+0x147/0x3df
[   49.887472]  __do_softirq+0x1d1/0x45f
[   49.889024]  do_softirq_own_stack+0x2a/0x40
[   49.891132]  </IRQ>
[   49.892728]  do_softirq+0x7c/0x81
[   49.894416]  __local_bh_enable_ip+0x81/0x98
[   49.896657]  ? ip_finish_output2+0x46c/0x51e
[   49.898792]  ip_finish_output2+0x495/0x51e
[   49.900538]  ip_finish_output+0x205/0x215
[   49.902511]  ? ip_finish_output+0x205/0x215
[   49.904191]  ip_output+0x7e/0x1e8
[   49.905967]  ? ip_fragment+0x7c/0x7c
[   49.908279]  ip_local_out+0x4f/0x56
[   49.910043]  ip_queue_xmit+0x38f/0x48e
[   49.911609]  tcp_transmit_skb+0x7d9/0x82b
[   49.913589]  tcp_connect+0x96a/0x9f9
[   49.914998]  tcp_v4_connect+0x46d/0x4b5
[   49.916728]  __inet_stream_connect+0xb8/0x2a9
[   49.918571]  ? trace_hardirqs_on+0xd/0xf
[   49.920339]  ? __local_bh_enable_ip+0x8d/0x98
[   49.922389]  ? lock_sock_nested+0x4c/0x9a
[   49.924028]  inet_stream_connect+0x38/0x4d
[   49.926285]  SyS_connect+0x74/0xa1
[   49.927847]  ? trace_hardirqs_on_caller+0x17b/0x197
[   49.929791]  ? trace_hardirqs_on_thunk+0x1a/0x1c
[   49.931564]  entry_SYSCALL_64_fastpath+0x1f/0xbe
[   49.933580] RIP: 0033:0x7f07baea4f20
[   49.935438] RSP: 002b:00007fff9f9c5a58 EFLAGS: 00000246 ORIG_RAX: 000000000000002a
[   49.938918] RAX: ffffffffffffffda RBX: 0000000000000046 RCX: 00007f07baea4f20
[   49.941662] RDX: 0000000000000010 RSI: 00007fff9f9c5c00 RDI: 0000000000000004
[   49.944152] RBP: 0000000000404a20 R08: 0000000000607019 R09: 1999999999999999
[   49.946972] R10: 0000000000000128 R11: 0000000000000246 R12: 0000000000000034
[   49.949501] R13: 0000000000000001 R14: 00007f07bb159540 R15: 00007fff9fa05f38
[   49.956488] (A bug in Linux doubles the requested buffer sizes)
[   49.956510] 
[   49.979889] Now starting the main loop
[   49.979912] 
[   50.630179]   0:       1 bytes   1143 times -->      0.08 Mbps in      92.82 usec
[   50.630210] 
[   51.252876]   1:       2 bytes   1077 times -->      0.17 Mbps in      91.96 usec
[   51.252899] 
[   51.913699]   2:       3 bytes   1087 times -->      0.25 Mbps in      89.86 usec
[   51.913722] 
[   52.329366]   3:       4 bytes    741 times -->      0.34 Mbps in      90.61 usec
[   52.329389] 
[   52.804064]   4:       6 bytes    827 times -->      0.50 Mbps in      91.68 usec
[   52.804086] 
[   53.131890]   5:       8 bytes    545 times -->      0.66 Mbps in      92.44 usec
[   53.131914] 
[   53.477970]   6:      12 bytes    676 times -->      1.12 Mbps in      81.68 usec
[   53.477991] 
[   53.743039]   7:      13 bytes    510 times -->      1.19 Mbps in      83.11 usec
[   53.743061] 
[   54.054901]   8:      16 bytes    555 times -->      1.46 Mbps in      83.79 usec
[   54.054919] 
[   54.381568]   9:      19 bytes    671 times -->      1.85 Mbps in      78.48 usec
[   54.381584] 
[   54.784169]  10:      21 bytes    804 times -->      2.03 Mbps in      78.91 usec


To reproduce:

        git clone https://github.com/intel/lkp-tests.git
        cd lkp-tests
        bin/lkp qemu -k <bzImage> job-script  # job-script is attached in this email



Thanks,
lkp

View attachment "config-4.14.0-rc4-00174-g81e5391" of type "text/plain" (118890 bytes)

View attachment "job-script" of type "text/plain" (6647 bytes)

Download attachment "dmesg.xz" of type "application/x-xz" (20176 bytes)

View attachment "netpipe" of type "text/plain" (8858 bytes)

Powered by blists - more mailing lists