Hi all,
I've started seeing the following in the latest -next kernel.
[ 531.127489] kernel BUG at mm/vmstat.c:1408!
[ 531.128157] invalid opcode: 0000 [#1] PREEMPT SMP KASAN
[ 531.128872] Modules linked in:
[ 531.129324] CPU: 6 PID: 407 Comm: kworker/6:1 Not tainted 4.4.0-rc5-next-20151218-sasha-00021-gaba8d84-dirty #2750
[ 531.130939] Workqueue: vmstat vmstat_update
[ 531.131741] task: ffff880204070000 ti: ffff880204078000 task.ti: ffff880204078000
[ 531.133189] RIP: vmstat_update (mm/vmstat.c:1408)
[ 531.134466] RSP: 0018:ffff88020407fbf8 EFLAGS: 00010293
[ 531.135132] RAX: 0000000000000006 RBX: ffff8800418e2fd8 RCX: 0000000000000000
[ 531.135995] RDX: 0000000000000007 RSI: ffffffff8c0982a0 RDI: ffffffff9b8bd6e4
[ 531.137475] RBP: ffff88020407fc18 R08: 0000000000000000 R09: ffff880204070230
[ 531.138304] R10: ffffffff8c0982a0 R11: 00000000e272b4f2 R12: ffff880204c1bf60
[ 531.139329] R13: ffff880204ab09c8 R14: ffff880204ab09b8 R15: ffff880204ab09b0
[ 531.140261] FS: 0000000000000000(0000) GS:ffff880204c00000(0000) knlGS:0000000000000000
[ 531.141218] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[ 531.142036] CR2: 00007f039a8c1944 CR3: 000000000ea28000 CR4: 00000000000006a0
[ 531.142752] Stack:
[ 531.142963] ffff880204c21000 ffff880204c21000 ffff880204c1bf60 ffff880204ab09c8
[ 531.144095] ffff88020407fd40 ffffffff813a8fea 0000000041b58ab3 ffffffff8e667cdb
[ 531.145258] ffff880204ab09f8 ffff880204c1bf68 ffff880204ab09c0 ffff880200000000
[ 531.146475] Call Trace:
[ 531.147037] process_one_work (./arch/x86/include/asm/preempt.h:22 kernel/workqueue.c:2045)
[ 531.150790] worker_thread (include/linux/compiler.h:218 include/linux/list.h:206 kernel/workqueue.c:2171)
[ 531.155176] kthread (kernel/kthread.c:209)
[ 531.158941] ret_from_fork (arch/x86/entry/entry_64.S:469)
[ 531.160654] Code: 75 1e be 79 00 00 00 48 c7 c7 80 0f 10 8c 89 45 e4 e8 cd 92 cd ff 8b 45 e4 c6 05 e1 c4 13 1a 01 89 c0 f0 48 0f ab 03 72 02 eb 0e <0f> 0b 48 c7 c7 c0 f1 47 90 e8 3d 03 ae 01 48 83 c4 08 5b 41 5c
All code
========
0: 75 1e jne 0x20
2: be 79 00 00 00 mov $0x79,%esi
7: 48 c7 c7 80 0f 10 8c mov $0xffffffff8c100f80,%rdi
e: 89 45 e4 mov %eax,-0x1c(%rbp)
11: e8 cd 92 cd ff callq 0xffffffffffcd92e3
16: 8b 45 e4 mov -0x1c(%rbp),%eax
19: c6 05 e1 c4 13 1a 01 movb $0x1,0x1a13c4e1(%rip) # 0x1a13c501
20: 89 c0 mov %eax,%eax
22: f0 48 0f ab 03 lock bts %rax,(%rbx)
27: 72 02 jb 0x2b
29: eb 0e jmp 0x39
2b:* 0f 0b ud2 <-- trapping instruction
2d: 48 c7 c7 c0 f1 47 90 mov $0xffffffff9047f1c0,%rdi
34: e8 3d 03 ae 01 callq 0x1ae0376
39: 48 83 c4 08 add $0x8,%rsp
3d: 5b pop %rbx
3e: 41 5c pop %r12
...
Code starting with the faulting instruction
===========================================
0: 0f 0b ud2
2: 48 c7 c7 c0 f1 47 90 mov $0xffffffff9047f1c0,%rdi
9: e8 3d 03 ae 01 callq 0x1ae034b
e: 48 83 c4 08 add $0x8,%rsp
12: 5b pop %rbx
13: 41 5c pop %r12
...
[ 531.164630] RIP vmstat_update (mm/vmstat.c:1408)
[ 531.165523] RSP <ffff88020407fbf8>
Thanks,
Sasha
On Fri, 18 Dec 2015, Sasha Levin wrote:
> [ 531.164630] RIP vmstat_update (mm/vmstat.c:1408)
Hmmm.. Yes we need to fold the diffs first before disabling the timer
otherwise the shepherd task may intervene.
Does this patch fix it?
Subject: quiet_vmstat: Avoid race with shepherd by folding counters first
We need to fold the counters first otherwise the shepherd task may
remotely reactivate the vmstat worker.
This also avoids the strange loop. Nothing can really increase the
counters at that point since we are in the cpu idle loop. So
folding the counters once is enough. Cancelling work that does
not exist is fine too so just avoid the branches completely.
Signed-off-by: Christoph Lameter <[email protected]>
Index: linux/mm/vmstat.c
===================================================================
--- linux.orig/mm/vmstat.c
+++ linux/mm/vmstat.c
@@ -1419,11 +1419,9 @@ void quiet_vmstat(void)
if (system_state != SYSTEM_RUNNING)
return;
- do {
- if (!cpumask_test_and_set_cpu(smp_processor_id(), cpu_stat_off))
- cancel_delayed_work(this_cpu_ptr(&vmstat_work));
-
- } while (refresh_cpu_vm_stats(false));
+ refresh_cpu_vm_stats(false);
+ cancel_delayed_work(this_cpu_ptr(&vmstat_work));
+ cpumask_set_cpu(smp_processor_id(), cpu_stat_off);
}
/*
On 12/21/2015 08:08 AM, Christoph Lameter wrote:
> On Fri, 18 Dec 2015, Sasha Levin wrote:
>
>> > [ 531.164630] RIP vmstat_update (mm/vmstat.c:1408)
> Hmmm.. Yes we need to fold the diffs first before disabling the timer
> otherwise the shepherd task may intervene.
>
> Does this patch fix it?
It didn't. With the patch I'm still seeing:
[ 1997.674112] kernel BUG at mm/vmstat.c:1408!
[ 1997.674930] invalid opcode: 0000 [#1] PREEMPT SMP KASAN
[ 1997.676252] Modules linked in:
[ 1997.676880] CPU: 4 PID: 14713 Comm: kworker/4:0 Not tainted 4.4.0-rc5-next-20151221-sasha-00020-g840272e-dirty #2753
[ 1997.679262] Workqueue: vmstat vmstat_update
[ 1997.680109] task: ffff88015bca0000 ti: ffff88015bcb8000 task.ti: ffff88015bcb8000
[ 1997.681279] RIP: 0010:[<ffffffffa2683c48>] [<ffffffffa2683c48>] vmstat_update+0x178/0x1a0
[ 1997.682810] RSP: 0018:ffff88015bcbfc00 EFLAGS: 00010297
[ 1997.683611] RAX: 0000000000000004 RBX: ffff8803d2801a18 RCX: 0000000000000000
[ 1997.684689] RDX: 0000000000000007 RSI: ffffffffad098220 RDI: ffffffffbc8be724
[ 1997.685750] RBP: ffff88015bcbfc20 R08: 0000000000000000 R09: ffff88015bca0230
[ 1997.686812] R10: ffffffffad098220 R11: ffff880180a1be78 R12: ffff880180a1be60
[ 1997.688087] R13: ffff880157b27908 R14: ffff880180a21000 R15: ffff880157b27900
[ 1997.689120] FS: 0000000000000000(0000) GS:ffff880180a00000(0000) knlGS:0000000000000000
[ 1997.690290] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[ 1997.691141] CR2: 00007f05e5690000 CR3: 0000000158699000 CR4: 00000000000006a0
[ 1997.692189] Stack:
[ 1997.692496] ffff880180a21000 ffff880157b27918 ffff880180a1be60 ffff880157b27908
[ 1997.693689] ffff88015bcbfd40 ffffffffa23aa40f ffffffffaf66686b ffff880157b27948
[ 1997.694851] ffff880180a1be68 ffff880100000000 ffff880157b27910 ffff880157b27920
[ 1997.696013] Call Trace:
[ 1997.696542] [<ffffffffa23aa40f>] process_one_work+0xacf/0x12a0
[ 1997.697516] [<ffffffffa23a9940>] ? cancel_delayed_work_sync+0x10/0x10
[ 1997.698889] [<fffffffface0df27>] ? __schedule+0x1127/0x14c0
[ 1997.699738] [<ffffffffa23e11bd>] ? get_parent_ip+0xd/0x40
[ 1997.700547] [<ffffffffa23e12d9>] ? preempt_count_add+0xe9/0x140
[ 1997.701426] [<ffffffffa23ab898>] worker_thread+0xcb8/0x1090
[ 1997.702259] [<ffffffffa23d2ad0>] ? load_mm_ldt+0x1f0/0x1f0
[ 1997.703084] [<ffffffffa23d5b53>] ? update_rq_clock+0x123/0x2e0
[ 1997.703962] [<ffffffffa23aabe0>] ? process_one_work+0x12a0/0x12a0
[ 1997.704896] [<ffffffffa23aabe0>] ? process_one_work+0x12a0/0x12a0
[ 1997.705804] [<ffffffffa23bf8ce>] kthread+0x31e/0x330
[ 1997.706551] [<ffffffffa23d3195>] ? finish_task_switch+0x6c5/0x970
[ 1997.707481] [<ffffffffa23bf5b0>] ? kthread_worker_fn+0x680/0x680
[ 1997.708374] [<ffffffffa23bf5b0>] ? kthread_worker_fn+0x680/0x680
[ 1997.709269] [<fffffffface1a50f>] ret_from_fork+0x3f/0x70
[ 1997.710067] [<ffffffffa23bf5b0>] ? kthread_worker_fn+0x680/0x680
[ 1997.710964] Code: 75 1e be 79 00 00 00 48 c7 c7 40 16 10 ad 89 45 e4 e8 2d 88 cd ff 8b 45 e4 c6 05 a0 a9 13 1a 01 89 c0 f0 48 0f ab 03 72 02 eb 0e <0f> 0b 48 c7 c7 c0 21 48 b1 e8 45 d6 ad 01 48 83 c4 08 5b 41 5c
[ 1997.714961] RIP [<ffffffffa2683c48>] vmstat_update+0x178/0x1a0
[ 1997.715852] RSP <ffff88015bcbfc00>
Thanks,
Sasha
On 12/21/2015 03:28 PM, Sasha Levin wrote:
> On 12/21/2015 08:08 AM, Christoph Lameter wrote:
>> > On Fri, 18 Dec 2015, Sasha Levin wrote:
>> >
>>>> >> > [ 531.164630] RIP vmstat_update (mm/vmstat.c:1408)
>> > Hmmm.. Yes we need to fold the diffs first before disabling the timer
>> > otherwise the shepherd task may intervene.
>> >
>> > Does this patch fix it?
> It didn't. With the patch I'm still seeing:
I've also noticed a new warning from the workqueue code which my scripts
didn't pick up before:
[ 3462.380681] BUG: workqueue lockup - pool cpus=2 node=2 flags=0x4 nice=0 stuck for 54s!
[ 3462.522041] workqueue vmstat: flags=0xc
[ 3462.527795] pwq 4: cpus=2 node=2 flags=0x0 nice=0 active=1/256
[ 3462.554836] pending: vmstat_update
Thanks,
Sasha
On Mon, 21 Dec 2015, Sasha Levin wrote:
> I've also noticed a new warning from the workqueue code which my scripts
> didn't pick up before:
>
> [ 3462.380681] BUG: workqueue lockup - pool cpus=2 node=2 flags=0x4 nice=0 stuck for 54s!
> [ 3462.522041] workqueue vmstat: flags=0xc
> [ 3462.527795] pwq 4: cpus=2 node=2 flags=0x0 nice=0 active=1/256
> [ 3462.554836] pending: vmstat_update
Does that mean that vmstat_update locks up or something that schedules it?
Also what workload triggers the BUG()?
Ran this here but no errors. Need config etc to reproduce.
On 12/21/2015 04:14 PM, Christoph Lameter wrote:
> On Mon, 21 Dec 2015, Sasha Levin wrote:
>
>> > I've also noticed a new warning from the workqueue code which my scripts
>> > didn't pick up before:
>> >
>> > [ 3462.380681] BUG: workqueue lockup - pool cpus=2 node=2 flags=0x4 nice=0 stuck for 54s!
>> > [ 3462.522041] workqueue vmstat: flags=0xc
>> > [ 3462.527795] pwq 4: cpus=2 node=2 flags=0x0 nice=0 active=1/256
>> > [ 3462.554836] pending: vmstat_update
> Does that mean that vmstat_update locks up or something that schedules it?
I think it means that vmstat_update didn't finish running (working).
> Also what workload triggers the BUG()?
Fuzzing with trinity inside a KVM guest. I've attached my config.
Thanks,
Sasha
On Thu, 24 Dec 2015, Sasha Levin wrote:
> >> > [ 3462.527795] pwq 4: cpus=2 node=2 flags=0x0 nice=0 active=1/256
> >> > [ 3462.554836] pending: vmstat_update
> > Does that mean that vmstat_update locks up or something that schedules it?
>
> I think it means that vmstat_update didn't finish running (working).
There is nothing in there that blocks.
> > Also what workload triggers the BUG()?
>
> Fuzzing with trinity inside a KVM guest. I've attached my config.
Ok will have a look.
Builds with your kernel config fail with
CHK include/generated/bounds.h
CHK include/generated/asm-offsets.h
CALL scripts/checksyscalls.sh
CHK include/generated/compile.h
make[1]: *** No rule to make target 'signing_key.pem', needed by
'certs/signing_key.x509'. Stop.
Makefile:967: recipe for target 'certs' failed
make: *** [certs] Error 2
make: *** Waiting for unfinished jobs....
CHK kernel/config_data.h
???