[<prev] [next>] [thread-next>] [day] [month] [year] [list]
Message-ID: <20180419030329.mvt3nhq263be4xtp@wfg-t540p.sh.intel.com>
Date: Thu, 19 Apr 2018 11:03:29 +0800
From: Fengguang Wu <fengguang.wu@...el.com>
To: Phil Sutter <phil@....cc>
Cc: Thomas Graf <tgraf@...g.ch>,
Daniel Borkmann <daniel@...earbox.net>,
Florian Westphal <fw@...len.de>,
Herbert Xu <herbert@...dor.apana.org.au>,
linux-kernel@...r.kernel.org, lkp@...org
Subject: [test_rhashtable] WARNING: suspicious RCU usage
Hello,
FYI this happens in mainline kernel 4.17.0-rc1.
It at least dates back to v4.1 .
[ 7.767898] test if its possible to exceed max_size 8192: no, ok
[ 7.768365] Average test time: 234002708
[ 7.768638] test inserting duplicates
[ 7.768907]
[ 7.769018] =============================
[ 7.769297] WARNING: suspicious RCU usage
[ 7.769576] 4.17.0-rc1 #46 Not tainted
[ 7.769836] -----------------------------
[ 7.770129] lib/test_rhashtable.c:502 suspicious rcu_dereference_protected() usage!
[ 7.770752]
[ 7.770752] other info that might help us debug this:
[ 7.770752]
[ 7.771298]
[ 7.771298] rcu_scheduler_active = 2, debug_locks = 1
[ 7.771743] no locks held by swapper/1.
[ 7.772011]
[ 7.772011] stack backtrace:
[ 7.772319] CPU: 0 PID: 1 Comm: swapper Not tainted 4.17.0-rc1 #46
[ 7.772739] Call Trace:
[ 7.772925] ? print_ht+0x66/0x25c:
print_ht at lib/test_rhashtable.c:502 (discriminator 7)
[ 7.773167] ? test_insert_dup+0x565/0x5d7:
test_insert_dup at lib/test_rhashtable.c:570
[ 7.773462] ? my_hashfn+0x10/0x10:
my_cmpfn at lib/test_rhashtable.c:94
[ 7.773706] ? kstrtoll_from_user+0x69/0x69:
jhash at include/linux/jhash.h:76
[ 7.773999] ? jhash+0x125/0x125:
jhash2 at include/linux/jhash.h:121
(inlined by) rhashtable_jhash2 at lib/rhashtable.c:932
jhash+0x125/0x125:
my_hashfn at lib/test_rhashtable.c:86
[ 7.774224] ? my_hashfn+0x10/0x10:
my_cmpfn at lib/test_rhashtable.c:94
[ 7.774462] ? rhashtable_rehash_alloc+0x63/0x63:
rht_deferred_worker at lib/rhashtable.c:413
[ 7.774780] ? test_rht_init+0x2ae/0x561:
test_insert_duplicates_run at lib/test_rhashtable.c:593 (discriminator 260)
(inlined by) test_rht_init at lib/test_rhashtable.c:748 (discriminator 260)
[ 7.775060] ? test_rhashtable+0x634/0x634
[ 7.775413] ? do_one_initcall+0x66/0x14f:
do_trace_initcall_finish at init/main.c:867
(inlined by) do_one_initcall at init/main.c:884
[ 7.775691] ? do_early_param+0x70/0x70:
repair_env_string at init/main.c:251
[ 7.775980] ? kernel_init_freeable+0xd6/0x173:
do_initcall_level at init/main.c:950
(inlined by) do_initcalls at init/main.c:959
(inlined by) do_basic_setup at init/main.c:977
(inlined by) kernel_init_freeable at init/main.c:1127
[ 7.776287] ? kernel_init_freeable+0xec/0x173:
do_initcall_level at init/main.c:950
(inlined by) do_initcalls at init/main.c:959
(inlined by) do_basic_setup at init/main.c:977
(inlined by) kernel_init_freeable at init/main.c:1127
[ 7.776595] ? rest_init+0x107/0x107:
kernel_init at init/main.c:1053
[ 7.776853] ? kernel_init+0x5/0xc7:
kernel_init at init/main.c:1055
[ 7.777104] ? ret_from_fork+0x2e/0x38:
ret_from_fork at arch/x86/entry/entry_32.S:311
[ 7.777364]
[ 7.777474] =============================
[ 7.777750] WARNING: suspicious RCU usage
[ 7.778031] 4.17.0-rc1 #46 Not tainted
[ 7.778290] -----------------------------
[ 7.778566] lib/test_rhashtable.c:507 suspicious rcu_dereference_protected() usage!
[ 7.779191]
[ 7.779191] other info that might help us debug this:
[ 7.779191]
[ 7.779732]
[ 7.779732] rcu_scheduler_active = 2, debug_locks = 1
[ 7.780190] no locks held by swapper/1.
[ 7.780456]
[ 7.780456] stack backtrace:
[ 7.780756] CPU: 0 PID: 1 Comm: swapper Not tainted 4.17.0-rc1 #46
[ 7.781179] Call Trace:
[ 7.781355] ? print_ht+0xb2/0x25c:
print_ht at lib/test_rhashtable.c:507 (discriminator 7)
[ 7.781595] ? test_insert_dup+0x565/0x5d7:
test_insert_dup at lib/test_rhashtable.c:570
[ 7.781878] ? my_hashfn+0x10/0x10:
my_cmpfn at lib/test_rhashtable.c:94
[ 7.782120] ? kstrtoll_from_user+0x69/0x69:
jhash at include/linux/jhash.h:76
[ 7.782409] ? jhash+0x125/0x125:
jhash2 at include/linux/jhash.h:121
(inlined by) rhashtable_jhash2 at lib/rhashtable.c:932
jhash+0x125/0x125:
my_hashfn at lib/test_rhashtable.c:86
[ 7.782633] ? my_hashfn+0x10/0x10:
my_cmpfn at lib/test_rhashtable.c:94
[ 7.782871] ? rhashtable_rehash_alloc+0x63/0x63:
rht_deferred_worker at lib/rhashtable.c:413
[ 7.783192] ? test_rht_init+0x2ae/0x561:
test_insert_duplicates_run at lib/test_rhashtable.c:593 (discriminator 260)
(inlined by) test_rht_init at lib/test_rhashtable.c:748 (discriminator 260)
[ 7.783472] ? test_rhashtable+0x634/0x634
[ 7.783824] ? do_one_initcall+0x66/0x14f:
do_trace_initcall_finish at init/main.c:867
(inlined by) do_one_initcall at init/main.c:884
[ 7.784105] ? do_early_param+0x70/0x70:
repair_env_string at init/main.c:251
[ 7.784371] ? kernel_init_freeable+0xd6/0x173:
do_initcall_level at init/main.c:950
(inlined by) do_initcalls at init/main.c:959
(inlined by) do_basic_setup at init/main.c:977
(inlined by) kernel_init_freeable at init/main.c:1127
[ 7.784677] ? kernel_init_freeable+0xec/0x173:
do_initcall_level at init/main.c:950
(inlined by) do_initcalls at init/main.c:959
(inlined by) do_basic_setup at init/main.c:977
(inlined by) kernel_init_freeable at init/main.c:1127
[ 7.784988] ? rest_init+0x107/0x107:
kernel_init at init/main.c:1053
[ 7.785237] ? kernel_init+0x5/0xc7:
kernel_init at init/main.c:1055
[ 7.785480] ? ret_from_fork+0x2e/0x38:
ret_from_fork at arch/x86/entry/entry_32.S:311
[ 7.785739]
[ 7.785849] =============================
[ 7.786129] WARNING: suspicious RCU usage
[ 7.786406] 4.17.0-rc1 #46 Not tainted
[ 7.786664] -----------------------------
[ 7.786950] lib/test_rhashtable.c:508 suspicious rcu_dereference_protected() usage!
[ 7.787570]
[ 7.787570] other info that might help us debug this:
[ 7.787570]
[ 7.788114]
[ 7.788114] rcu_scheduler_active = 2, debug_locks = 1
[ 7.788555] no locks held by swapper/1.
[ 7.788820]
[ 7.788820] stack backtrace:
[ 7.789126] CPU: 0 PID: 1 Comm: swapper Not tainted 4.17.0-rc1 #46
[ 7.789544] Call Trace:
[ 7.789718] ? print_ht+0xfa/0x25c:
print_ht at lib/test_rhashtable.c:508 (discriminator 9)
[ 7.789962] ? test_insert_dup+0x565/0x5d7:
test_insert_dup at lib/test_rhashtable.c:570
[ 7.790250] ? my_hashfn+0x10/0x10:
my_cmpfn at lib/test_rhashtable.c:94
[ 7.790494] ? kstrtoll_from_user+0x69/0x69:
jhash at include/linux/jhash.h:76
[ 7.790781] ? jhash+0x125/0x125:
jhash2 at include/linux/jhash.h:121
(inlined by) rhashtable_jhash2 at lib/rhashtable.c:932
jhash+0x125/0x125:
my_hashfn at lib/test_rhashtable.c:86
[ 7.791008] ? my_hashfn+0x10/0x10:
my_cmpfn at lib/test_rhashtable.c:94
[ 7.791245] ? rhashtable_rehash_alloc+0x63/0x63:
rht_deferred_worker at lib/rhashtable.c:413
[ 7.791568] ? test_rht_init+0x2ae/0x561:
test_insert_duplicates_run at lib/test_rhashtable.c:593 (discriminator 260)
(inlined by) test_rht_init at lib/test_rhashtable.c:748 (discriminator 260)
[ 7.791839] ? test_rhashtable+0x634/0x634
[ 7.792196] ? do_one_initcall+0x66/0x14f:
do_trace_initcall_finish at init/main.c:867
(inlined by) do_one_initcall at init/main.c:884
[ 7.792472] ? do_early_param+0x70/0x70:
repair_env_string at init/main.c:251
[ 7.792736] ? kernel_init_freeable+0xd6/0x173:
do_initcall_level at init/main.c:950
(inlined by) do_initcalls at init/main.c:959
(inlined by) do_basic_setup at init/main.c:977
(inlined by) kernel_init_freeable at init/main.c:1127
[ 7.793045] ? kernel_init_freeable+0xec/0x173:
do_initcall_level at init/main.c:950
(inlined by) do_initcalls at init/main.c:959
(inlined by) do_basic_setup at init/main.c:977
(inlined by) kernel_init_freeable at init/main.c:1127
[ 7.793359] ? rest_init+0x107/0x107:
kernel_init at init/main.c:1053
[ 7.793608] ? kernel_init+0x5/0xc7:
kernel_init at init/main.c:1055
[ 7.793851] ? ret_from_fork+0x2e/0x38:
ret_from_fork at arch/x86/entry/entry_32.S:311
[ 7.794115]
[ 7.794225] =============================
[ 7.794502] WARNING: suspicious RCU usage
[ 7.794779] 4.17.0-rc1 #46 Not tainted
[ 7.795043] -----------------------------
[ 7.795320] lib/test_rhashtable.c:519 suspicious rcu_dereference_protected() usage!
[ 7.795944]
[ 7.795944] other info that might help us debug this:
[ 7.795944]
[ 7.796487]
[ 7.796487] rcu_scheduler_active = 2, debug_locks = 1
[ 7.796942] no locks held by swapper/1.
[ 7.797208]
[ 7.797208] stack backtrace:
[ 7.797509] CPU: 0 PID: 1 Comm: swapper Not tainted 4.17.0-rc1 #46
[ 7.797934] Call Trace:
[ 7.798109] ? print_ht+0x164/0x25c:
rht_obj at include/linux/rhashtable.h:234 (discriminator 7)
(inlined by) print_ht at lib/test_rhashtable.c:520 (discriminator 7)
[ 7.798356] ? test_insert_dup+0x565/0x5d7:
test_insert_dup at lib/test_rhashtable.c:570
[ 7.798639] ? my_hashfn+0x10/0x10:
my_cmpfn at lib/test_rhashtable.c:94
[ 7.798878] ? kstrtoll_from_user+0x69/0x69:
jhash at include/linux/jhash.h:76
[ 7.799176] ? jhash+0x125/0x125:
jhash2 at include/linux/jhash.h:121
(inlined by) rhashtable_jhash2 at lib/rhashtable.c:932
jhash+0x125/0x125:
my_hashfn at lib/test_rhashtable.c:86
[ 7.799402] ? my_hashfn+0x10/0x10:
my_cmpfn at lib/test_rhashtable.c:94
[ 7.799641] ? rhashtable_rehash_alloc+0x63/0x63:
rht_deferred_worker at lib/rhashtable.c:413
[ 7.799963] ? test_rht_init+0x2ae/0x561:
test_insert_duplicates_run at lib/test_rhashtable.c:593 (discriminator 260)
(inlined by) test_rht_init at lib/test_rhashtable.c:748 (discriminator 260)
[ 7.800248] ? test_rhashtable+0x634/0x634
[ 7.800601] ? do_one_initcall+0x66/0x14f:
do_trace_initcall_finish at init/main.c:867
(inlined by) do_one_initcall at init/main.c:884
[ 7.800878] ? do_early_param+0x70/0x70:
repair_env_string at init/main.c:251
[ 7.801147] ? kernel_init_freeable+0xd6/0x173:
do_initcall_level at init/main.c:950
(inlined by) do_initcalls at init/main.c:959
(inlined by) do_basic_setup at init/main.c:977
(inlined by) kernel_init_freeable at init/main.c:1127
[ 7.801452] ? kernel_init_freeable+0xec/0x173:
do_initcall_level at init/main.c:950
(inlined by) do_initcalls at init/main.c:959
(inlined by) do_basic_setup at init/main.c:977
(inlined by) kernel_init_freeable at init/main.c:1127
[ 7.801758] ? rest_init+0x107/0x107:
kernel_init at init/main.c:1053
[ 7.802010] ? kernel_init+0x5/0xc7:
kernel_init at init/main.c:1055
[ 7.802254] ? ret_from_fork+0x2e/0x38:
ret_from_fork at arch/x86/entry/entry_32.S:311
[ 7.802515]
[ 7.802625] =============================
[ 7.802904] WARNING: suspicious RCU usage
[ 7.803181] 4.17.0-rc1 #46 Not tainted
[ 7.803448] -----------------------------
[ 7.803725] lib/test_rhashtable.c:529 suspicious rcu_dereference_protected() usage!
[ 7.804349]
[ 7.804349] other info that might help us debug this:
[ 7.804349]
[ 7.804892]
[ 7.804892] rcu_scheduler_active = 2, debug_locks = 1
[ 7.805336] no locks held by swapper/1.
[ 7.805601]
[ 7.805601] stack backtrace:
[ 7.805904] CPU: 0 PID: 1 Comm: swapper Not tainted 4.17.0-rc1 #46
[ 7.806324] Call Trace:
[ 7.806499] ? print_ht+0x1e1/0x25c:
print_ht at lib/test_rhashtable.c:529 (discriminator 9)
[ 7.806753] ? test_insert_dup+0x565/0x5d7:
test_insert_dup at lib/test_rhashtable.c:570
[ 7.807040] ? my_hashfn+0x10/0x10:
my_cmpfn at lib/test_rhashtable.c:94
[ 7.807278] ? kstrtoll_from_user+0x69/0x69:
jhash at include/linux/jhash.h:76
[ 7.807567] ? jhash+0x125/0x125:
jhash2 at include/linux/jhash.h:121
(inlined by) rhashtable_jhash2 at lib/rhashtable.c:932
jhash+0x125/0x125:
my_hashfn at lib/test_rhashtable.c:86
[ 7.807792] ? my_hashfn+0x10/0x10:
my_cmpfn at lib/test_rhashtable.c:94
[ 7.808033] ? rhashtable_rehash_alloc+0x63/0x63:
rht_deferred_worker at lib/rhashtable.c:413
[ 7.808352] ? test_rht_init+0x2ae/0x561:
test_insert_duplicates_run at lib/test_rhashtable.c:593 (discriminator 260)
(inlined by) test_rht_init at lib/test_rhashtable.c:748 (discriminator 260)
[ 7.808625] ? test_rhashtable+0x634/0x634
[ 7.808983] ? do_one_initcall+0x66/0x14f:
do_trace_initcall_finish at init/main.c:867
(inlined by) do_one_initcall at init/main.c:884
[ 7.809260] ? do_early_param+0x70/0x70:
repair_env_string at init/main.c:251
[ 7.809525] ? kernel_init_freeable+0xd6/0x173:
do_initcall_level at init/main.c:950
(inlined by) do_initcalls at init/main.c:959
(inlined by) do_basic_setup at init/main.c:977
(inlined by) kernel_init_freeable at init/main.c:1127
[ 7.809831] ? kernel_init_freeable+0xec/0x173:
do_initcall_level at init/main.c:950
(inlined by) do_initcalls at init/main.c:959
(inlined by) do_basic_setup at init/main.c:977
(inlined by) kernel_init_freeable at init/main.c:1127
[ 7.810149] ? rest_init+0x107/0x107:
kernel_init at init/main.c:1053
[ 7.810399] ? kernel_init+0x5/0xc7:
kernel_init at init/main.c:1055
[ 7.810642] ? ret_from_fork+0x2e/0x38:
ret_from_fork at arch/x86/entry/entry_32.S:311
[ 7.810913]
[ 7.810913] ---- ht: ----
[ 7.810913] bucket[1] -> [[ val 1 (tid=0) ]] -> [[ val 21 (tid=1) ]]
[ 7.810913] -------------
[ 7.813358]
Attached the full dmesg, kconfig and reproduce scripts.
Thanks,
Fengguang
View attachment "dmesg-openwrt-lkp-hsw01-15:20180418191103:i386-randconfig-c0-04181855:4.17.0-rc1:46" of type "text/plain" (41712 bytes)
View attachment ".config" of type "text/plain" (97476 bytes)
View attachment "reproduce-openwrt-lkp-hsw01-15:20180418191103:i386-randconfig-c0-04181855:4.17.0-rc1:46" of type "text/plain" (919 bytes)
Powered by blists - more mailing lists