Date:   Sat, 11 Nov 2017 18:37:58 +0800
From:   Fengguang Wu <fengguang.wu@...el.com>
To:     linux-kernel@...r.kernel.org
Cc:     Peter Zijlstra <peterz@...radead.org>,
        Ingo Molnar <mingo@...hat.com>,
        Arnaldo Carvalho de Melo <acme@...nel.org>,
        Alexander Shishkin <alexander.shishkin@...ux.intel.com>,
        Jiri Olsa <jolsa@...hat.com>,
        Namhyung Kim <namhyung@...nel.org>,
        David Carrillo-Cisneros <davidcc@...gle.com>,
        Tejun Heo <tj@...nel.org>,
        Hari Bathini <hbathini@...ux.vnet.ibm.com>,
        Thomas Gleixner <tglx@...utronix.de>
Subject: [perf_swevent_add] WARNING: CPU: 0 PID: 393 at
 kernel/events/core.c:7735 perf_swevent_add+0xe0/0x14f

Hello,

FYI this happens in 4.14.0-rc8, however not a new bug.

[   24.754743] rcu-perf:    1 writer-duration:   100 39878755
[   24.780867] ACPI: Preparing to enter system sleep state S5
[   24.781683] reboot: Power down
[   24.783666] acpi_power_off called
[   24.800288] ------------[ cut here ]------------
[   24.801132] WARNING: CPU: 0 PID: 393 at kernel/events/core.c:7735 perf_swevent_add+0xe0/0x14f:
perf_swevent_add at kernel/events/core.c:7735
[   24.802811] Modules linked in:
[   24.803339] CPU: 0 PID: 393 Comm: trinity-main Not tainted 4.14.0-rc8 #1
[   24.804443] task: ffff88001731a740 task.stack: ffffc90000900000
[   24.805426] RIP: 0010:perf_swevent_add+0xe0/0x14f:
perf_swevent_add at kernel/events/core.c:7735
[   24.806193] RSP: 0018:ffffc90000903b48 EFLAGS: 00010046
[   24.807061] RAX: 0000000000000003 RBX: ffff88001ef21000 RCX: 0000000000000000
[   24.808229] RDX: 0000000000000000 RSI: 0000000000000001 RDI: ffffffff82874090
[   24.809388] RBP: ffffc90000903b68 R08: ffff88001ed8e400 R09: 0000000000000000
[   24.810552] R10: ffff88001d5d3c40 R11: 0000000000000000 R12: 0000000000000000
[   24.811697] R13: 0000000000000001 R14: 0000000000000001 R15: ffff88001ef21000
[   24.812867] FS:  00007f7fb3bae700(0000) GS:ffff88001d400000(0000) knlGS:0000000000000000
[   24.814165] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   24.815113] CR2: 000000000090b138 CR3: 0000000017121000 CR4: 00000000000006b0
[   24.816282] Call Trace:
[   24.816710]  event_sched_in+0x17d/0x3a2:
event_sched_in at kernel/events/core.c:2105
[   24.817365]  group_sched_in+0x6b/0x1ce:
group_sched_in at kernel/events/core.c:2145
[   24.818011]  ctx_sched_in+0x756/0x825:
ctx_sched_in at kernel/events/core.c:3156
[   24.818619]  perf_event_sched_in+0x89/0x92:
perf_event_sched_in at kernel/events/core.c:2304
[   24.819298]  ctx_resched+0xcf/0xe5:
ctx_resched at kernel/events/core.c:2352
[   24.819872]  __perf_install_in_context+0x198/0x1c5:
__perf_install_in_context at kernel/events/core.c:2397
[   24.820685]  ? perf_ctx_unlock+0x36/0x36:
remote_function at kernel/events/core.c:68
[   24.821336]  remote_function+0x2b/0x7d:
remote_function at kernel/events/core.c:87
[   24.821969]  generic_exec_single+0xab/0x1c9:
generic_exec_single at arch/x86/include/asm/irqflags.h:158
[   24.822665]  ? perf_ctx_unlock+0x36/0x36:
remote_function at kernel/events/core.c:68
[   24.823325]  smp_call_function_single+0x11b/0x16e:
smp_call_function_single at kernel/smp.c:301
[   24.824105]  task_function_call+0x37/0x5d:
task_function_call at kernel/events/core.c:116
[   24.824771]  ? task_function_call+0x37/0x5d:
task_function_call at kernel/events/core.c:116
[   24.825483]  ? ctx_resched+0xe5/0xe5:
__perf_install_in_context at kernel/events/core.c:2362
[   24.826086]  perf_install_in_context+0x151/0x223:
perf_install_in_context at kernel/events/core.c:2474
[   24.826836]  SyS_perf_event_open+0x1505/0x17c1
[   24.827593]  ? __do_page_fault+0x8f3/0x9cc:
__do_page_fault at arch/x86/mm/fault.c:1482
[   24.828324]  entry_SYSCALL_64_fastpath+0x23/0xc2:
entry_SYSCALL_64_fastpath at arch/x86/entry/entry_64.S:206
[   24.829089] RIP: 0033:0x7f7fb36c36d9
[   24.829682] RSP: 002b:00007ffe98c0cb98 EFLAGS: 00000246 ORIG_RAX: 000000000000012a
[   24.830927] RAX: ffffffffffffffda RBX: 00007ffe98c0cdc0 RCX: 00007f7fb36c36d9
[   24.832068] RDX: ffffffffffffffff RSI: 0000000000000000 RDI: 000000000068b000
[   24.833227] RBP: 0000000000402daa R08: 0000000000000000 R09: 0000000000000004
[   24.834372] R10: ffffffffffffffff R11: 0000000000000246 R12: 0000000000000004
[   24.835556] R13: 0000000000002000 R14: 0000000000909120 R15: 000000000001aed1
[   24.836714] Code: 48 c7 c7 90 40 87 82 41 0f 94 c5 31 c9 31 d2 4d 89 ee 44 89 f6 e8 ed c8 fb ff 49 8d 45 02 48 ff 04 c5 40 08 a1 82 4d 85 e4 75 02 <0f> ff 31 c9 31 d2 49 83 c5 02 44 89 f6 48 c7 c7 60 40 87 82 e8
[   24.841049] ---[ end trace dc902c71c8e40d96 ]---
[   25.885079] ------------[ cut here ]------------
[   25.885079] ------------[ cut here ]------------
[   25.887731] WARNING: CPU: 0 PID: 10 at kernel/sched/core.c:1179 set_task_cpu+0x19e/0x38d:
set_task_cpu at kernel/sched/core.c:1179 (discriminator 11)
[   25.889364] Modules linked in:
[   25.889955] CPU: 0 PID: 10 Comm: migration/0 Tainted: G        W       4.14.0-rc8 #1
[   25.891371] task: ffff88001d0e0000 task.stack: ffffc90000050000
[   25.892497] RIP: 0010:set_task_cpu+0x19e/0x38d:
set_task_cpu at kernel/sched/core.c:1179 (discriminator 11)
[   25.893306] RSP: 0018:ffffc90000053d78 EFLAGS: 00010002
[   25.894201] RAX: 0000000000000003 RBX: ffff88001ec20000 RCX: 0000000000000000
[   25.895384] RDX: 0000000000000000 RSI: 0000000000000001 RDI: ffffffff82858130
[   25.896524] RBP: ffffc90000053da0 R08: 0000000000000000 R09: 00000005bbd0ec00
[   25.897676] R10: ffffc90001a53e90 R11: 0000000000000000 R12: 0000000000000001
[   25.898822] R13: 0000000000000001 R14: 0000000000000001 R15: ffff88001d5d9c01
[   25.899972] FS:  0000000000000000(0000) GS:ffff88001d400000(0000) knlGS:0000000000000000
[   25.901256] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   25.902220] CR2: 00007f7fb3ad9149 CR3: 000000001761f000 CR4: 00000000000006b0
[   25.903402] Call Trace:
[   25.903842]  move_queued_task+0x23c/0x4be:
move_queued_task at kernel/sched/sched.h:929
[   25.904509]  __migrate_task+0xb3/0xf8:
__migrate_task at kernel/sched/core.c:967
[   25.905284]  migration_cpu_stop+0xca/0x133:
migration_cpu_stop at kernel/sched/core.c:1005
[   25.906172]  ? sched_ttwu_pending+0xf1/0xf1:
migration_cpu_stop at kernel/sched/core.c:978
[   25.907061]  cpu_stopper_thread+0xc8/0x1ea:
cpu_stopper_thread at kernel/stop_machine.c:481
[   25.908200]  ? smpboot_thread_fn+0x5/0x2bb:
smpboot_thread_fn at kernel/smpboot.c:107
[   25.909033]  smpboot_thread_fn+0x29f/0x2bb:
smpboot_thread_fn at kernel/smpboot.c:164
[   25.909864]  ? smpboot_park_thread+0x43/0x43:
smpboot_thread_fn at kernel/smpboot.c:107
[   25.910678]  kthread+0x174/0x17c:
kthread at kernel/kthread.c:233
[   25.911236]  ? kthread_create_on_node+0x3f/0x3f:
kthread at kernel/kthread.c:190
[   25.911981]  ret_from_fork+0x2a/0x40:
ret_from_fork at arch/x86/entry/entry_64.S:438
[   25.912588] Code: 48 c7 c7 30 81 85 82 31 c9 45 0f b6 e7 31 d2 44 89 e6 e8 6b bb 0c 00 49 63 c4 48 83 c0 02 48 ff 04 c5 28 7d 99 82 45 84 ff 74 02 <0f> ff 31 c9 31 d2 44 89 e6 48 c7 c7 00 81 85 82 e8 42 bb 0c 00
[   25.915978] ---[ end trace dc902c71c8e40d97 ]---
[   25.916899] sched: Unexpected reschedule of offline CPU#1!

Attached the full dmesg, kconfig and reproduce script.

The perf_swevent_add() warning is not easily reproducible and exists since 4.13.
The set_task_cpu() warning looks more common and exists since 4.14-rc1.

Thanks,
Fengguang

View attachment "dmesg-quantal-kbuild-11:20171111034037:x86_64-randconfig-it0-11031244:4.14.0-rc8:1" of type "text/plain" (82146 bytes)

View attachment ".config" of type "text/plain" (131578 bytes)

View attachment "reproduce-quantal-kbuild-11:20171111034037:x86_64-randconfig-it0-11031244:4.14.0-rc8:1" of type "text/plain" (880 bytes)

Powered by blists - more mailing lists