[arch_copy_kprobe] WARNING: CPU: 0 PID: 1 at mm/vmalloc.c:301 vmalloc_to_page+0x2bf/0x416
by Fengguang Wu
Hello,
FYI this happens in mainline kernel 4.15.0-rc1.
It looks like a new regression. Bisect is on the way.
It occurs in 2 out of 11 boots.
[ 5.083644] rcu-perf:--- Start of test: nreaders=0 nwriters=1 verbose=1 shutdown=1
[ 5.085168] rcu-torture: Creating rcu_perf_shutdown task
[ 5.092218] rcu-torture: Creating rcu_perf_writer task
[ 5.093360] rcu-perf: rcu_perf_writer task started
[ 5.099058] Kprobe smoke test: started
[ 5.101137] WARNING: CPU: 0 PID: 1 at mm/vmalloc.c:301 vmalloc_to_page+0x2bf/0x416:
vmalloc_to_page at mm/vmalloc.c:301
[ 5.102564] Modules linked in:
[ 5.103087] CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.15.0-rc1 #189
[ 5.104031] task: ffff88001d068000 task.stack: ffff88001d06c000
[ 5.104031] RIP: 0010:vmalloc_to_page+0x2bf/0x416:
vmalloc_to_page at mm/vmalloc.c:301
[ 5.104031] RSP: 0000:ffff88001d06fce8 EFLAGS: 00010293
[ 5.104031] RAX: 0000000000000003 RBX: ffffffffc0200000 RCX: 0000000000000000
[ 5.104031] RDX: 0000000000000000 RSI: 0000000000000001 RDI: ffffffff9ed6e210
[ 5.104031] RBP: ffff880018815008 R08: ffffffff9e344ec6 R09: 0000000000000001
[ 5.104031] R10: ffff88001d06fc90 R11: 0000000000000b2c R12: 0000000000000000
[ 5.104031] R13: 0000000000000063 R14: 0000000000000001 R15: ffff88001d06fd61
[ 5.104031] FS: 0000000000000000(0000) GS:ffff88001d600000(0000) knlGS:0000000000000000
[ 5.104031] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 5.104031] CR2: 0000000000000000 CR3: 0000000018812000 CR4: 00000000000406f0
[ 5.104031] Call Trace:
[ 5.104031] ? 0xffffffffc01ff000
[ 5.104031] text_poke+0x4f/0x297:
text_poke at arch/x86/kernel/alternative.c:709
[ 5.104031] ? 0xffffffffc01ff002
[ 5.104031] arch_copy_kprobe+0xf7/0x106:
arch_copy_kprobe at arch/x86/kernel/kprobes/core.c:474
[ 5.104031] arch_prepare_kprobe+0x8c/0xc4:
arch_prepare_kprobe at arch/x86/kernel/kprobes/core.c:491
[ 5.104031] register_kprobe+0x6a8/0x875:
register_kprobe at kernel/kprobes.c:1567
[ 5.104031] ? do_early_param+0xb6/0xb6:
repair_env_string at init/main.c:245
[ 5.104031] ? init_test_probes+0x49/0x4bb:
test_kprobe at kernel/test_kprobes.c:69
(inlined by) init_test_probes at kernel/test_kprobes.c:377
[ 5.104031] init_test_probes+0x49/0x4bb:
test_kprobe at kernel/test_kprobes.c:69
(inlined by) init_test_probes at kernel/test_kprobes.c:377
[ 5.104031] init_kprobes+0x276/0x281:
init_kprobes at kernel/kprobes.c:2277
[ 5.104031] ? debugfs_kprobe_init+0xf7/0xf7:
init_kprobes at kernel/kprobes.c:2225
[ 5.104031] do_one_initcall+0x99/0x1a0:
do_one_initcall at init/main.c:826
[ 5.104031] ? do_early_param+0xb6/0xb6:
repair_env_string at init/main.c:245
[ 5.104031] kernel_init_freeable+0x11e/0x1e8:
do_initcall_level at init/main.c:891
(inlined by) do_initcalls at init/main.c:900
(inlined by) do_basic_setup at init/main.c:918
(inlined by) kernel_init_freeable at init/main.c:1066
[ 5.104031] ? rest_init+0x270/0x270:
kernel_init at init/main.c:993
[ 5.104031] kernel_init+0x5/0x156:
kernel_init at init/main.c:995
[ 5.104031] ret_from_fork+0x24/0x30:
ret_from_fork at arch/x86/entry/entry_64.S:447
[ 5.104031] Code: 9e 48 39 c8 49 89 c4 41 0f 95 c6 31 c9 31 d2 44 89 f6 e8 36 48 f3 ff 49 63 c6 48 83 c0 02 48 ff 04 c5 c8 3b f0 9e 4d 39 ec 74 02 <0f> ff 31 d2 31 c9 48 c7 c7 e0 e1 d6 9e 44 89 f6 e8 0d 48 f3 ff
[ 5.104031] ---[ end trace 1e069188d28709ac ]---
[ 5.193423] Kprobe smoke test: passed successfully
Attached the full dmesg, kconfig and reproduce scripts.
Thanks,
Fengguang
3 years, 1 month
[lkp-robot] [sched] 106b167fed: netperf.Throughput_tps -22.1% regression
by kernel test robot
Greeting,
FYI, we noticed a -22.1% regression of netperf.Throughput_tps due to commit:
commit: 106b167fed0c54a1f9db472c910979d65fcfd629 ("sched: force update of blocked load of idle cpus")
git://internal_merge_and_test_tree devel-catchup-201710171950
in testcase: netperf
on test machine: qemu-system-x86_64 -enable-kvm -cpu host -smp 4 -m 5G
with following parameters:
ip: ipv4
runtime: 300s
nr_threads: 25%
cluster: cs-localhost
test: UDP_RR
test-description: Netperf is a benchmark that can be use to measure various aspect of networking performance.
test-url: http://www.netperf.org/netperf/
Details are as below:
-------------------------------------------------------------------------------------------------->
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
testcase/path_params/tbox_group/run: netperf/ipv4-300s-25%-cs-localhost-UDP_RR/vm-lkp-a04
6be53520ad8f87dc 106b167fed0c54a1f9db472c91
---------------- --------------------------
50 49 netperf.time.percent_of_cpu_this_job_got
6952 -22% 5414 netperf.Throughput_tps
2060002 -22% 1599840 netperf.time.voluntary_context_switches
15109 39% 21011 vmstat.system.in
28445 -21% 22564 vmstat.system.cs
80.65 4% 83.70 boot-time.boot
215 3% 222 boot-time.idle
netperf.Throughput_tps
7400 +-+------------------------------------------------------------------+
7200 +-+ .+ .+ .+ .+ |
|+ +.+ .++.+ .+++ ++ :.++ ++ ++ : .++ + |
7000 +-+ + ++ ++.+++.+++ + +.+ : :+.++ +. + + |
6800 +-++ ++.+ + + +|
6600 +-+ |
6400 +-+ |
| |
6200 +-+ |
6000 +-+ |
5800 +-+ O |
5600 +-+ O O O O |
O O OOO O O O O O OOO O |
5400 +O+OO O OO OO OO |
5200 +-+------------------------------------------------------------------+
[*] bisect-good sample
[O] bisect-bad sample
Disclaimer:
Results have been estimated based on internal Intel analysis and are provided
for informational purposes only. Any difference in system hardware or software
design or configuration may affect actual performance.
Thanks,
Xiaolong
3 years, 1 month
[ 0.003333] BUG: KASAN: use-after-scope in console_unlock+0x605/0xcc0
by Fengguang Wu
Hello,
FYI this happens in mainline kernel v4.15-rc1 .
It shows up after v4.14 . Bisect is on the way.
It occurs in 4 out of 4 boots.
[ 0.003333] RCU callback double-/use-after-free debug enabled.
[ 0.003333] RCU CPU stall warnings timeout set to 100 (rcu_cpu_stall_timeout).
[ 0.003333] Tasks RCU enabled.
[ 0.003333] NR_IRQS: 4352, nr_irqs: 48, preallocated irqs: 16
[ 0.003333] ==================================================================
[ 0.003333] BUG: KASAN: use-after-scope in console_unlock+0x605/0xcc0:
atomic_read at arch/x86/include/asm/atomic.h:27
(inlined by) static_key_count at include/linux/jump_label.h:191
(inlined by) static_key_false at include/linux/jump_label.h:201
(inlined by) trace_console_rcuidle at include/trace/events/printk.h:10
(inlined by) call_console_drivers at kernel/printk/printk.c:1556
(inlined by) console_unlock at kernel/printk/printk.c:2233
[ 0.003333] Write of size 4 at addr ffffffff83607aa0 by task swapper/0
[ 0.003333]
[ 0.003333] CPU: 0 PID: 0 Comm: swapper Not tainted 4.15.0-rc1 #1
[ 0.003333] Call Trace:
[ 0.003333] ? print_address_description+0x4f/0x3c0:
print_address_description at mm/kasan/report.c:253
[ 0.003333] ? console_unlock+0x605/0xcc0:
atomic_read at arch/x86/include/asm/atomic.h:27
(inlined by) static_key_count at include/linux/jump_label.h:191
(inlined by) static_key_false at include/linux/jump_label.h:201
(inlined by) trace_console_rcuidle at include/trace/events/printk.h:10
(inlined by) call_console_drivers at kernel/printk/printk.c:1556
(inlined by) console_unlock at kernel/printk/printk.c:2233
[ 0.003333] ? kasan_report+0x304/0x390:
kasan_report_error at mm/kasan/report.c:352
(inlined by) kasan_report at mm/kasan/report.c:409
[ 0.003333] ? console_unlock+0x605/0xcc0:
atomic_read at arch/x86/include/asm/atomic.h:27
(inlined by) static_key_count at include/linux/jump_label.h:191
(inlined by) static_key_false at include/linux/jump_label.h:201
(inlined by) trace_console_rcuidle at include/trace/events/printk.h:10
(inlined by) call_console_drivers at kernel/printk/printk.c:1556
(inlined by) console_unlock at kernel/printk/printk.c:2233
[ 0.003333] ? wake_up_klogd+0x180/0x180:
console_unlock at kernel/printk/printk.c:2138
[ 0.003333] ? _raw_spin_unlock_irqrestore+0xcf/0xf0:
__raw_spin_unlock_irqrestore at include/linux/spinlock_api_smp.h:161
(inlined by) _raw_spin_unlock_irqrestore at kernel/locking/spinlock.c:191
[ 0.003333] ? __down_trylock_console_sem+0xf8/0x120:
__down_trylock_console_sem at kernel/printk/printk.c:234
[ 0.003333] ? __down_trylock_console_sem+0x106/0x120:
__down_trylock_console_sem at kernel/printk/printk.c:235
[ 0.003333] ? vprintk_emit+0x63e/0x6f0:
vprintk_emit at kernel/printk/printk.c:1757
[ 0.003333] ? vprintk_func+0x11e/0x130:
vprintk_func at kernel/printk/printk_safe.c:379
[ 0.003333] ? printk+0xaf/0xcf:
printk at kernel/printk/printk.c:1824
[ 0.003333] ? show_regs_print_info+0x40/0x40:
printk at kernel/printk/printk.c:1824
[ 0.003333] ? __flush_tlb_all+0x1e/0x31:
__flush_tlb_global at arch/x86/include/asm/paravirt.h:298
(inlined by) __flush_tlb_all at arch/x86/include/asm/tlbflush.h:293
[ 0.003333] ? native_flush_tlb_global+0x5/0xa0:
native_flush_tlb_global at arch/x86/kernel/paravirt.c:199
[ 0.003333] ? kasan_init+0x276/0x306:
kasan_init at arch/x86/mm/kasan_init_64.c:349
[ 0.003333] ? setup_arch+0x1bb0/0x1cad:
setup_arch at arch/x86/kernel/setup.c:1236
[ 0.003333] ? reserve_standard_io_resources+0x88/0x88:
setup_arch at arch/x86/kernel/setup.c:829
[ 0.003333] ? vprintk_emit+0x6dc/0x6f0:
vprintk_emit at kernel/printk/printk.c:1761
[ 0.003333] ? vprintk_func+0x125/0x130:
vprintk_func at kernel/printk/printk_safe.c:380
[ 0.003333] ? printk+0xaf/0xcf:
printk at kernel/printk/printk.c:1824
[ 0.003333] ? show_regs_print_info+0x40/0x40:
printk at kernel/printk/printk.c:1824
[ 0.003333] ? trace_hardirqs_on+0x220/0x220:
trace_hardirqs_off at kernel/trace/trace_irqsoff.c:799
[ 0.003333] ? __early_make_pgtable+0x2a5/0x308:
__early_make_pgtable at arch/x86/kernel/head64.c:251
[ 0.003333] ? boot_cpu_init+0x16/0x56:
set_bit at arch/x86/include/asm/bitops.h:76
(inlined by) cpumask_set_cpu at include/linux/cpumask.h:297
(inlined by) set_cpu_online at include/linux/cpumask.h:799
(inlined by) boot_cpu_init at kernel/cpu.c:2012
[ 0.003333] ? start_kernel+0xe7/0x8cd:
add_latent_entropy at include/linux/random.h:26
(inlined by) start_kernel at init/main.c:535
[ 0.003333] ? thread_stack_cache_init+0x37/0x37
[ 0.003333] ? x86_cpuid_vendor+0xbe/0xd0:
x86_cpuid_vendor at arch/x86/include/asm/microcode.h:125
[ 0.003333] ? x86_family+0x2f/0x40:
x86_family at arch/x86/lib/cpu.c:14
[ 0.003333] ? load_ucode_bsp+0x3c4/0x46f:
load_ucode_bsp at arch/x86/kernel/cpu/microcode/core.c:189
[ 0.003333] ? x86_early_init_platform_quirks+0x146/0x1a1:
x86_early_init_platform_quirks at arch/x86/kernel/platform-quirks.c:31
[ 0.003333] ? secondary_startup_64+0xa5/0xb0:
secondary_startup_64 at arch/x86/kernel/head_64.S:237
[ 0.003333]
[ 0.003333] Memory state around the buggy address:
[ 0.003333] ffffffff83607980: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 0.003333] ffffffff83607a00: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 0.003333] >ffffffff83607a80: f1 f1 f1 f1 f8 f2 f2 f2 f2 f2 f2 f2 00 f2 f2 f2
Attached the full dmesg, kconfig and reproduce scripts.
Thanks,
Fengguang
3 years, 1 month
[lkp-robot] [torture] b151f93a71: INFO:rcu_preempt_detected_stalls_on_CPUs/tasks
by kernel test robot
FYI, we noticed the following commit (built with gcc-6):
commit: b151f93a71fc9fecb560e823a92402d882516483 ("torture: Eliminate torture_runnable")
https://git.kernel.org/cgit/linux/kernel/git/paulmck/linux-rcu.git dev.2017.11.21a
in testcase: boot
on test machine: qemu-system-i386 -enable-kvm -smp 2 -m 320M
caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):
+------------------------------------------------+------------+------------+
| | 3d9d746535 | b151f93a71 |
+------------------------------------------------+------------+------------+
| boot_successes | 0 | 0 |
| boot_failures | 76 | 88 |
| genirq:Flags_mismatch_irq##(ttyS0)vs.#(sir_ir) | 76 | 88 |
| INFO:rcu_preempt_self-detected_stall_on_CPU | 67 | 38 |
| EIP:__do_softirq | 67 | 38 |
| EIP:_raw_spin_unlock_irqrestore | 67 | 38 |
| INFO:rcu_preempt_detected_stalls_on_CPUs/tasks | 0 | 35 |
| EIP:preempt_count_sub | 0 | 1 |
| EIP:delay_tsc | 0 | 5 |
| EIP:preempt_count_add | 0 | 1 |
+------------------------------------------------+------------+------------+
[ 116.310716] INFO: rcu_preempt detected stalls on CPUs/tasks:
[ 116.311764] Tasks blocked on level-0 rcu_node (CPUs 0-0): P31
[ 116.312856] (detected by 0, t=10002 jiffies, g=-88, c=-89, q=352)
[ 116.314001] rcu_torture_rea R running task 7168 31 2 0x80000000
[ 116.315329] Call Trace:
[ 116.315801] __schedule+0x493/0x620
[ 116.316450] ? __softirqentry_text_start+0x8/0x8
[ 116.317306] preempt_schedule_irq+0x4a/0x70
[ 116.318083] resume_kernel+0x27/0x29
[ 116.318753] EIP: preempt_count_sub+0x130/0x140
[ 116.319579] EFLAGS: 00200297 CPU: 0
[ 116.320241] EAX: 47bd1665 EBX: 00000000 ECX: 00000000 EDX: 47bd1665
[ 116.321574] ESI: 7a647087 EDI: 0000000b EBP: 504e7ec4 ESP: 504e7ec4
[ 116.322821] DS: 007b ES: 007b FS: 0000 GS: 00e0 SS: 0068
[ 116.323808] ? delay_tsc+0x65/0xd0
[ 116.324463] ? delay_tsc+0x65/0xd0
[ 116.325095] ? __queue_work+0x300/0x370
[ 116.325810] delay_tsc+0x65/0xd0
[ 116.326440] __delay+0xe/0x10
[ 116.327007] __const_udelay+0x25/0x30
[ 116.327675] rcu_read_delay+0x8a/0x110
[ 116.328414] ? kvm_sched_clock_read+0x8/0x20
[ 116.329242] rcu_torture_reader+0x189/0x320
[ 116.330019] ? rcu_torture_reader+0x320/0x320
[ 116.330833] kthread+0x103/0x110
[ 116.331513] ? rcu_torture_timer_cb+0x10/0x10
[ 116.332331] ? __kthread_create_on_node+0x140/0x140
[ 116.333247] ret_from_fork+0x19/0x24
[ 116.333938] rcu_torture_rea R running task 7168 31 2 0x80000000
[ 116.335236] Call Trace:
[ 116.335712] __schedule+0x493/0x620
[ 116.336367] ? __softirqentry_text_start+0x8/0x8
[ 116.337217] preempt_schedule_irq+0x4a/0x70
[ 116.338003] resume_kernel+0x27/0x29
[ 116.338674] EIP: preempt_count_sub+0x130/0x140
[ 116.339490] EFLAGS: 00200297 CPU: 0
[ 116.340162] EAX: 47bd1665 EBX: 00000000 ECX: 00000000 EDX: 47bd1665
[ 116.341300] ESI: 7a647087 EDI: 0000000b EBP: 504e7ec4 ESP: 504e7ec4
[ 116.342470] DS: 007b ES: 007b FS: 0000 GS: 00e0 SS: 0068
[ 116.343449] ? delay_tsc+0x65/0xd0
[ 116.344080] ? delay_tsc+0x65/0xd0
[ 116.344762] ? __queue_work+0x300/0x370
[ 116.345471] delay_tsc+0x65/0xd0
[ 116.346062] __delay+0xe/0x10
[ 116.346642] __const_udelay+0x25/0x30
[ 116.347339] rcu_read_delay+0x8a/0x110
[ 116.348027] ? kvm_sched_clock_read+0x8/0x20
[ 116.348829] rcu_torture_reader+0x189/0x320
[ 116.349621] ? rcu_torture_reader+0x320/0x320
[ 116.350421] kthread+0x103/0x110
[ 116.351038] ? rcu_torture_timer_cb+0x10/0x10
[ 116.351853] ? __kthread_create_on_node+0x140/0x140
[ 116.352742] ret_from_fork+0x19/0x24
[ 116.353432] rcu_preempt kthread starved for 9974 jiffies! g4294967208 c4294967207 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x402 ->cpu=0
[ 116.355517] rcu_preempt I 7464 8 2 0x80000000
[ 116.356543] Call Trace:
[ 116.357008] __schedule+0x493/0x620
[ 116.357682] schedule+0x24/0x40
[ 116.358291] schedule_timeout+0x330/0x3b0
[ 116.359024] ? preempt_count_sub+0xea/0x140
[ 116.359806] ? collect_expired_timers+0xb0/0xb0
[ 116.360660] rcu_gp_kthread+0x6bf/0xef0
[ 116.361364] ? _raw_spin_unlock_irq+0x32/0x50
[ 116.362178] ? __schedule+0x4cd/0x620
[ 116.362874] kthread+0x103/0x110
[ 116.363476] ? rcu_implicit_dynticks_qs+0x3b0/0x3b0
[ 116.364377] ? __kthread_create_on_node+0x140/0x140
[ 116.365290] ret_from_fork+0x19/0x24
[ 116.367322] sir_ir sir_ir.0: Trapped in interrupt
[ 116.369468] sir_ir sir_ir.0: Trapped in interrupt
[ 116.371646] sir_ir sir_ir.0: Trapped in interrupt
[ 116.373797] sir_ir sir_ir.0: Trapped in interrupt
[ 116.375953] sir_ir sir_ir.0: Trapped in interrupt
[ 116.378112] sir_ir sir_ir.0: Trapped in interrupt
[ 116.380277] sir_ir sir_ir.0: Trapped in interrupt
[ 116.382452] sir_ir sir_ir.0: Trapped in interrupt
[ 116.384602] sir_ir sir_ir.0: Trapped in interrupt
[ 116.386762] sir_ir sir_ir.0: Trapped in interrupt
[ 116.388917] sir_ir sir_ir.0: Trapped in interrupt
[ 116.391059] sir_ir sir_ir.0: Trapped in interrupt
[ 116.393248] sir_ir sir_ir.0: Trapped in interrupt
[ 116.395407] sir_ir sir_ir.0: Trapped in interrupt
[ 116.397562] sir_ir sir_ir.0: Trapped in interrupt
[ 116.399723] sir_ir sir_ir.0: Trapped in interrupt
[ 116.401899] sir_ir sir_ir.0: Trapped in interrupt
[ 116.404055] sir_ir sir_ir.0: Trapped in interrupt
[ 116.406212] sir_ir sir_ir.0: Trapped in interrupt
[ 116.408371] sir_ir sir_ir.0: Trapped in interrupt
[ 116.410528] sir_ir sir_ir.0: Trapped in interrupt
[ 116.412710] sir_ir sir_ir.0: Trapped in interrupt
[ 116.414859] sir_ir sir_ir.0: Trapped in interrupt
[ 116.417008] sir_ir sir_ir.0: Trapped in interrupt
[ 116.419165] sir_ir sir_ir.0: Trapped in interrupt
[ 116.421342] sir_ir sir_ir.0: Trapped in interrupt
[ 116.424341] sir_ir sir_ir.0: Trapped in interrupt
[ 116.426505] sir_ir sir_ir.0: Trapped in interrupt
[ 116.428662] sir_ir sir_ir.0: Trapped in interrupt
[ 116.430817] sir_ir sir_ir.0: Trapped in interrupt
[ 116.432982] sir_ir sir_ir.0: Trapped in interrupt
[ 116.435134] sir_ir sir_ir.0: Trapped in interrupt
[ 116.437290] sir_ir sir_ir.0: Trapped in interrupt
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,
Xiaolong
3 years, 1 month