frequent lockups in 3.18rc4

I'm not sure how long this goes back (3.17 was fine afair) but I'm seeing these several times a day lately..

I've got a local hack to dump loadavg on traces, and as you can see in that example, the machine was really busy, but we were at least making progress before the trace spewed, and the machine rebooted. (I have reboot-on-lockup sysctl set, without it, the machine just wedges indefinitely shortly after the spew).

The trace doesn't really enlighten me as to what we should be doing to prevent this though.

ideas?

I can try to bisect it, but it takes hours before it happens, so it might take days to complete, and the next few weeks are complicated timewise..

NMI watchdog: BUG: soft lockup - CPU#3 stuck for 22s! [trinity-c129:25570]

irq event stamp: 74224
hardirqs last  enabled at (74223): [<ffffffff9c875664>] restore_args+0x0/0x30
hardirqs last disabled at (74224): [<ffffffff9c8759aa>] apic_timer_interrupt+0x6a/0x80
softirqs last  enabled at (74222): [<ffffffff9c07f43a>] __do_softirq+0x26a/0x6f0
softirqs last disabled at (74209): [<ffffffff9c07fb4d>] irq_exit+0x13d/0x170
CPU: 3 PID: 25570 Comm: trinity-c129 Not tainted 3.18.0-rc4+ #83 [loadavg: 198.04 186.66 181.58 24/442 26708]
RIP: 0010:[<ffffffff9c11e98a>]  [<ffffffff9c11e98a>] generic_exec_single+0xea/0x1d0
Call Trace:
 [<ffffffff9c048b20>] ? leave_mm+0x210/0x210
 [<ffffffff9c048b20>] ? leave_mm+0x210/0x210
 [<ffffffff9c11ead6>] smp_call_function_single+0x66/0x110
 [<ffffffff9c048b20>] ? leave_mm+0x210/0x210
 [<ffffffff9c11f021>] smp_call_function_many+0x2f1/0x390
 [<ffffffff9c049300>] flush_tlb_mm_range+0xe0/0x370
 [<ffffffff9c1d95a2>] tlb_flush_mmu_tlbonly+0x42/0x50
 [<ffffffff9c1d9cb5>] tlb_finish_mmu+0x45/0x50
 [<ffffffff9c1daf59>] zap_page_range_single+0x119/0x170
 [<ffffffff9c1db140>] unmap_mapping_range+0x140/0x1b0
 [<ffffffff9c1c7edd>] shmem_fallocate+0x43d/0x540
 [<ffffffff9c223aba>] do_fallocate+0x12a/0x1c0
 [<ffffffff9c1f0bd3>] SyS_madvise+0x3d3/0x890
 [<ffffffff9c874c89>] tracesys_phase2+0xd4/0xd9
Kernel panic - not syncing: softlockup: hung tasks

Plus, judging by the fact that there's a stale "leave_mm+0x210/0x210" (wouldn't that be the *next* function, namely do_flush_tlb_all()) pointer on the stack, I suspect that whole range-flushing doesn't even trigger, and we are flushing everything.

But since you say "several times a day", just for fun, can you test the follow-up patch to that one-liner fix that Will Deacon posted today (Subject: "[PATCH] mmu_gather: move minimal range calculations into generic code"). That does some further cleanup in this area.

Quoted 4 lines

The trace doesn't really enlighten me as to what we should be doing to prevent this though.

ideas?

I can't say I have any ideas except to point at the TLB range patch, and quite frankly, I don't see how that would matter.

If Will's patch doesn't make a difference, what about reverting that ce9ec37bddb6? Although it really *is* a "obvious bugfix", and I really don't see why any of this would be noticeable on x86 (it triggered issues on ARM64, but that was because ARM64 cared much more about the exact range).

Quoted 3 lines

I can try to bisect it, but it takes hours before it happens, so it might take days to complete, and the next few weeks are complicated timewise..

Hmm. Even narrowing it down a bit might help, ie if you could get say four bisections in over a day, and see if that at least says "ok, it's likely one of these pulls".

But yeah, I can see it being painful, so maybe a quick check of the TLB ones, even if I can't for the life see why they would possibly matter.

Quoted 2 lines · Dave Jones

I'm not sure how long this goes back (3.17 was fine afair) but I'm seeing these several times a day lately..

Plus, judging by the fact that there's a stale "leave_mm+0x210/0x210" (wouldn't that be the *next* function, namely do_flush_tlb_all()) pointer on the stack, I suspect that whole range-flushing doesn't even trigger, and we are flushing everything.

Quoted 10 lines

NMI watchdog: BUG: soft lockup - CPU#3 stuck for 22s! [trinity-c129:25570]

RIP: 0010:[<ffffffff9c11e98a>]  [<ffffffff9c11e98a>] generic_exec_single+0xea/0x1d0

Call Trace:
 [<ffffffff9c048b20>] ? leave_mm+0x210/0x210
 [<ffffffff9c048b20>] ? leave_mm+0x210/0x210
 [<ffffffff9c11ead6>] smp_call_function_single+0x66/0x110
 [<ffffffff9c048b20>] ? leave_mm+0x210/0x210
 [<ffffffff9c11f021>] smp_call_function_many+0x2f1/0x390
 [<ffffffff9c049300>] flush_tlb_mm_range+0xe0/0x370

So this looks more like a smp function call fuckup.

I assume Dave is running that stuff on KVM. So it might be worth while to look at the IPI magic there.

Quoted 4 lines · Thomas Gleixner

So this looks more like a smp function call fuckup.

I assume Dave is running that stuff on KVM. So it might be worth while to look at the IPI magic there.

no, bare metal.

This stale entry is not relevant here because the thing is stuck in generic_exec_single().

So from smp_call_function_many() we end up via smp_call_function_single() in generic_exec_single().

So the only ways to get stuck there are:

     csd_lock(csd);
and
     csd_lock_wait(csd);

Quoted 8 lines · Dave Jones

Quoted 4 lines · Thomas Gleixner

So this looks more like a smp function call fuckup.

I assume Dave is running that stuff on KVM. So it might be worth while to look at the IPI magic there.

no, bare metal.

Ok, but that does not change the fact that we are stuck in smp_function_call land.

Enabling softlockup_all_cpu_backtrace will probably not help much as we will end up waiting for csd_lock again :(

Is the machine still accesible when this happens? If yes, we might enable a few trace points and functions and read out the trace buffer. If not, we could just panic the machine and dump the trace buffer over serial.

But since you say "several times a day", just for fun, can you test the follow-up patch to that one-liner fix that Will Deacon posted today (Subject: "[PATCH] mmu_gather: move minimal range calculations into generic code"). That does some further cleanup in this area.

If Will's patch doesn't make a difference, what about reverting that ce9ec37bddb6? Although it really *is* a "obvious bugfix", and I really don't see why any of this would be noticeable on x86 (it triggered issues on ARM64, but that was because ARM64 cared much more about the exact range).

Quoted 4 lines · Linus Torvalds

But since you say "several times a day", just for fun, can you test the follow-up patch to that one-liner fix that Will Deacon posted today (Subject: "[PATCH] mmu_gather: move minimal range calculations into generic code"). That does some further cleanup in this area.

A few hours ago it hit the NMI watchdog again with that patch applied. Incomplete trace, but it looks different based on what did make it over. Different RIP at least.

[65155.054155] NMI watchdog: BUG: soft lockup - CPU#1 stuck for 22s! [trinity-c127:12559]
[65155.054573] irq event stamp: 296752
[65155.054589] hardirqs last  enabled at (296751): [<ffffffff9d87403d>] _raw_spin_unlock_irqrestore+0x5d/0x80
[65155.054625] hardirqs last disabled at (296752): [<ffffffff9d875cea>] apic_timer_interrupt+0x6a/0x80
[65155.054657] softirqs last  enabled at (296188): [<ffffffff9d259943>] bdi_queue_work+0x83/0x270
[65155.054688] softirqs last disabled at (296184): [<ffffffff9d259920>] bdi_queue_work+0x60/0x270
[65155.054721] CPU: 1 PID: 12559 Comm: trinity-c127 Not tainted 3.18.0-rc4+ #84 [loadavg: 209.68 187.90 185.33 34/431 17515]
[65155.054795] task: ffff88023f664680 ti: ffff8801649f0000 task.ti: ffff8801649f0000
[65155.054820] RIP: 0010:[<ffffffff9d87403f>]  [<ffffffff9d87403f>] _raw_spin_unlock_irqrestore+0x5f/0x80
[65155.054852] RSP: 0018:ffff8801649f3be8  EFLAGS: 00000292
[65155.054872] RAX: ffff88023f664680 RBX: 0000000000000007 RCX: 0000000000000007
[65155.054895] RDX: 00000000000029e0 RSI: ffff88023f664ea0 RDI: ffff88023f664680
[65155.054919] RBP: ffff8801649f3bf8 R08: 0000000000000000 R09: 0000000000000000
[65155.055956] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
[65155.056985] R13: ffff8801649f3b58 R14: ffffffff9d3e7d0e R15: 00000000000003e0
[65155.058037] FS:  00007f0dc957c700(0000) GS:ffff880244200000(0000) knlGS:0000000000000000
[65155.059083] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[65155.060121] CR2: 00007f0dc958e000 CR3: 000000022f31e000 CR4: 00000000001407e0
[65155.061152] DR0: 00007f54162bc000 DR1: 00007feb92c3d000 DR2: 0000000000000000
[65155.062180] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000600
[65155.063202] Stack:

And that's all she wrote.

Quoted 5 lines

If Will's patch doesn't make a difference, what about reverting that ce9ec37bddb6? Although it really *is* a "obvious bugfix", and I really don't see why any of this would be noticeable on x86 (it triggered issues on ARM64, but that was because ARM64 cared much more about the exact range).

I'll try that next, and check in on it tomorrow.

Quoted 2 lines

I'll try that next, and check in on it tomorrow.

No luck. Died even faster this time.

Quoted 4 lines · Dave Jones

Quoted 2 lines

I'll try that next, and check in on it tomorrow.

No luck. Died even faster this time.

Yeah, and your other lockups haven't even been TLB related. Not that they look like anything else *either*.

I have no ideas left. I'd go for a bisection

Quoted 17 lines · Thomas Gleixner

Quoted 8 lines · Dave Jones

Quoted 4 lines · Thomas Gleixner

So this looks more like a smp function call fuckup.

I assume Dave is running that stuff on KVM. So it might be worth while to look at the IPI magic there.

no, bare metal.

Ok, but that does not change the fact that we are stuck in smp_function_call land.

Enabling softlockup_all_cpu_backtrace will probably not help much as we will end up waiting for csd_lock again :(

Quoted 4 lines

Is the machine still accesible when this happens? If yes, we might enable a few trace points and functions and read out the trace buffer. If not, we could just panic the machine and dump the trace buffer over serial.

No, it wedges solid. Even though it says something like "CPU3 locked up", aparently all cores also get stuck.

9 times out of 10 it doesn't stay alive long enough to even get the full trace out over usb-serial.

Before starting a bisection you could try and disable transparent_hugepages. There are strange bugs, that were introduced during this merge-window, in this area. See: https://lkml.org/lkml/2014/11/4/144
https://lkml.org/lkml/2014/11/4/904
http://thread.gmane.org/gmane.linux.kernel.mm/124451

I'm not sure how long this goes back (3.17 was fine afair) but I'm seeing these several times a day lately..

NMI watchdog: BUG: soft lockup - CPU#3 stuck for 22s! [trinity-c129:25570]

irq event stamp: 74224
hardirqs last  enabled at (74223): [<ffffffff9c875664>] restore_args+0x0/0x30
hardirqs last disabled at (74224): [<ffffffff9c8759aa>] apic_timer_interrupt+0x6a/0x80
softirqs last  enabled at (74222): [<ffffffff9c07f43a>] __do_softirq+0x26a/0x6f0
softirqs last disabled at (74209): [<ffffffff9c07fb4d>] irq_exit+0x13d/0x170
CPU: 3 PID: 25570 Comm: trinity-c129 Not tainted 3.18.0-rc4+ #83 [loadavg: 198.04 186.66 181.58 24/442 26708]
task: ffff880213442f00 ti: ffff8801ea714000 task.ti: ffff8801ea714000
RIP: 0010:[<ffffffff9c11e98a>]  [<ffffffff9c11e98a>] generic_exec_single+0xea/0x1d0
RSP: 0018:ffff8801ea717a08  EFLAGS: 00000202
RAX: ffff880213442f00 RBX: ffffffff9c875664 RCX: 0000000000000006
RDX: 0000000000001370 RSI: ffff880213443790 RDI: ffff880213442f00
RBP: ffff8801ea717a68 R08: ffff880242b56690 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000000 R12: ffff8801ea717978
R13: ffff880213442f00 R14: ffff8801ea714000 R15: ffff880213442f00
FS:  00007f240994e700(0000) GS:ffff880244600000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 0000000000000004 CR3: 000000019a017000 CR4: 00000000001407e0
DR0: 00007fb3367e0000 DR1: 00007f82542ab000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000600
Stack:
 ffffffff9ce4c620 0000000000000000 ffffffff9c048b20 ffff8801ea717b18

 0000000000000003 0000000052e0da3d ffffffff9cc7ef3c 0000000000000002
 ffffffff9c048b20 ffff8801ea717b18 0000000000000001 0000000000000003
Call Trace:
 [<ffffffff9c048b20>] ? leave_mm+0x210/0x210
 [<ffffffff9c048b20>] ? leave_mm+0x210/0x210
 [<ffffffff9c11ead6>] smp_call_function_single+0x66/0x110
 [<ffffffff9c048b20>] ? leave_mm+0x210/0x210
 [<ffffffff9c11f021>] smp_call_function_many+0x2f1/0x390

 [<ffffffff9c049300>] flush_tlb_mm_range+0xe0/0x370
 [<ffffffff9c1d95a2>] tlb_flush_mmu_tlbonly+0x42/0x50
 [<ffffffff9c1d9cb5>] tlb_finish_mmu+0x45/0x50
 [<ffffffff9c1daf59>] zap_page_range_single+0x119/0x170
 [<ffffffff9c1db140>] unmap_mapping_range+0x140/0x1b0
 [<ffffffff9c1c7edd>] shmem_fallocate+0x43d/0x540
 [<ffffffff9c0b111b>] ? preempt_count_sub+0xab/0x100
 [<ffffffff9c0cdac7>] ? prepare_to_wait+0x27/0x80
 [<ffffffff9c2287f3>] ? __sb_start_write+0x103/0x1d0
 [<ffffffff9c223aba>] do_fallocate+0x12a/0x1c0
 [<ffffffff9c1f0bd3>] SyS_madvise+0x3d3/0x890
 [<ffffffff9c1a40d2>] ? context_tracking_user_exit+0x52/0x260
 [<ffffffff9c013ebd>] ? syscall_trace_enter_phase2+0x10d/0x3d0
 [<ffffffff9c874c89>] tracesys_phase2+0xd4/0xd9
Code: 63 c7 48 89 de 48 89 df 48 c7 c2 c0 50 1d 00 48 03 14 c5 40 b9 f2 9c e8 d5 ea 2b 00 84 c0 74 0b e9 bc 00 00 00 0f 1f 40 00 f3 90 <f6> 43 18 01 75 f8 31 c0 48 8b 4d c8 65 48 33 0c 25 28 00 00 00 
Kernel panic - not syncing: softlockup: hung tasks

I've got a local hack to dump loadavg on traces, and as you can see in that example, the machine was really busy, but we were at least making progress before the trace spewed, and the machine rebooted. (I have reboot-on-lockup sysctl set, without it, the machine just wedges indefinitely shortly after the spew).

The trace doesn't really enlighten me as to what we should be doing to prevent this though.

ideas?
I can try to bisect it, but it takes hours before it happens, so it might take days to complete, and the next few weeks are complicated timewise..

Dave

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/

Quoted 3 lines

Quoted 1 line

I'll try that next, and check in on it tomorrow.

No luck. Died even faster this time.

Yeah, and your other lockups haven't even been TLB related. Not that they look like anything else *either*.

I have no ideas left. I'd go for a bisection - rather than try random things, at least bisection will get us a smaller set of suspects if you can go through a few cycles of it. Even if you decide that you want to run for most of a day before you are convinced it's all good, a couple of days should get you a handful of bisection points (that's assuming you hit a couple of bad ones too that turn bad in a shorter while). And 4 or five bisections should get us from 11k commits down to the ~600 commit range. That would be a huge improvement.

It could a completely different cause for lockup, but seeing this now has me wondering if perhaps it's something unrelated to the kernel. I have recollection of running late .17rc's for days without incident, and I'm pretty sure .17 was ok too. But a few weeks ago I did upgrade that test box to the Fedora 21 beta. Which means I have a new gcc. I'm not sure I really trust 4.9.1 yet, so maybe I'll see if I can get 4.8 back on there and see if that's any better.

Judging by the code disassembly, it's the "csd_lock_wait(csd)" at the end.

Quoted 3 lines · Linus Torvalds

Judging by the code disassembly, it's the "csd_lock_wait(csd)" at the end.

Btw, looking at this, I grew really suspicious of this code in csd_unlock():

        WARN_ON((csd->flags & CSD_FLAG_WAIT) && !(csd->flags & CSD_FLAG_LOCK));

because that makes no sense at all. It basically removes a sanity check, yet that sanity check makes a hell of a lot of sense. Unlocking a CSD that is not locked is *wrong*.

The crazy code code comes from commit c84a83e2aaab ("smp: don't warn about csd->flags having CSD_FLAG_LOCK cleared for !wait") by Jens, but the explanation and the code is pure crap.

There is no way in hell that it is ever correct to unlock an entry that isn't locked, so that whole CSD_FLAG_WAIT thing is buggy as hell.

The explanation in commit c84a83e2aaab says that "blk-mq reuses the request potentially immediately" and claims that that is somehow ok, but that's utter BS. Even if you don't ever wait for it, the CSD lock bit fundamentally also protects the "csd->llist" pointer. So what that commit actually does is to just remove a safety check, and do so in a very unsafe manner. And apparently block-mq re-uses something THAT IS STILL ACTIVELY IN USE. That's just horrible.

Now, I think we might do this differently, by doing the "csd_unlock()" after we have loaded everything from the csd, but *before* actually calling the callback function. That would seem to be equivalent (interrupts are disabled, so this will not result in the func() possibly called twice), more efficient, _and_ not remove a useful check.

Hmm? Completely untested patch attached. Jens, does this still work for you?

Am I missing something?

kernel/smp.c +1 -5

@@ -19,7 +19,6 @@
 
 enum {
 	CSD_FLAG_LOCK		= 0x01,
-	CSD_FLAG_WAIT		= 0x02,
 };
 
 struct call_function_data {

@@ -126,7 +125,7 @@ static void csd_lock(struct call_single_data *csd)
 
 static void csd_unlock(struct call_single_data *csd)
 {
-	WARN_ON((csd->flags & CSD_FLAG_WAIT) && !(csd->flags & CSD_FLAG_LOCK));
+	WARN_ON(!(csd->flags & CSD_FLAG_LOCK));
 
 	/*
 	 * ensure we're all done before releasing data:

@@ -173,9 +172,6 @@ static int generic_exec_single(int cpu, struct call_single_data *csd,
 	csd->func = func;
 	csd->info = info;
 
-	if (wait)
-		csd->flags |= CSD_FLAG_WAIT;
-
 	/*
 	 * The list addition should be visible before sending the IPI
 	 * handler locks the list to pull the entry off it because of

Review

Quoted 7 lines · Linus Torvalds

(quoted diff) +4 -1

 	llist_for_each_entry_safe(csd, csd_next, entry, llist) {
-		csd->func(csd->info);
+		smp_call_func_t func = csd->func;
+		void *info = csd->info;
 		csd_unlock(csd);
+
+		func(info);

No, that won't work for synchronous calls:

    CPU 0      	    		CPU 1

    csd_lock(csd);
    queue_csd();
    ipi();
				func = csd->func;
				info = csd->info;
				csd_unlock(csd);
    csd_lock_wait();    
				func(info);

The csd_lock_wait() side will succeed and therefor assume that the call has been completed while the function has not been called at all. Interesting explosions to follow.

The proper solution is to revert that commit and properly analyze the problem which Jens was trying to solve and work from there.

Quoted 22 lines · Thomas Gleixner

kernel/smp.c static void flush_smp_call_function_queu · line 268

Quoted 7 lines · Linus Torvalds

kernel/smp.c +4 -1

 	llist_for_each_entry_safe(csd, csd_next, entry, llist) {
-		csd->func(csd->info);
+		smp_call_func_t func = csd->func;
+		void *info = csd->info;
 		csd_unlock(csd);
+
+		func(info);

No, that won't work for synchronous calls:

    CPU 0      	    		CPU 1

    csd_lock(csd);
    queue_csd();
    ipi();
				func = csd->func;
				info = csd->info;
				csd_unlock(csd);
    csd_lock_wait();    
				func(info);

Quoted 6 lines

The csd_lock_wait() side will succeed and therefor assume that the call has been completed while the function has not been called at all. Interesting explosions to follow.

The proper solution is to revert that commit and properly analyze the problem which Jens was trying to solve and work from there.

So a combo of both (Jens and yours) might do the trick. Patch below.

I think what Jens was trying to solve is:

     CPU 0      	    		CPU 1
 
     csd_lock(csd);
     queue_csd();
     ipi();
 				csd->func(csd->info);
     wait_for_completion(csd);
				   complete(csd);
     reuse_csd(csd);		
				csd_unlock(csd);

Quoted 3 lines · Linus Torvalds

Judging by the code disassembly, it's the "csd_lock_wait(csd)" at the end.

Btw, looking at this, I grew really suspicious of this code in csd_unlock():

        WARN_ON((csd->flags & CSD_FLAG_WAIT) && !(csd->flags & CSD_FLAG_LOCK));

because that makes no sense at all. It basically removes a sanity check, yet that sanity check makes a hell of a lot of sense. Unlocking a CSD that is not locked is *wrong*.

The crazy code code comes from commit c84a83e2aaab ("smp: don't warn about csd->flags having CSD_FLAG_LOCK cleared for !wait") by Jens, but the explanation and the code is pure crap.

There is no way in hell that it is ever correct to unlock an entry that isn't locked, so that whole CSD_FLAG_WAIT thing is buggy as hell.

The explanation in commit c84a83e2aaab says that "blk-mq reuses the request potentially immediately" and claims that that is somehow ok, but that's utter BS. Even if you don't ever wait for it, the CSD lock bit fundamentally also protects the "csd->llist" pointer. So what that commit actually does is to just remove a safety check, and do so in a very unsafe manner. And apparently block-mq re-uses something THAT IS STILL ACTIVELY IN USE. That's just horrible.

Quoted 21 lines · Linus Torvalds

Quoted 3 lines · Linus Torvalds

Judging by the code disassembly, it's the "csd_lock_wait(csd)" at the end.

Btw, looking at this, I grew really suspicious of this code in csd_unlock():

        WARN_ON((csd->flags & CSD_FLAG_WAIT) && !(csd->flags & CSD_FLAG_LOCK));

because that makes no sense at all. It basically removes a sanity check, yet that sanity check makes a hell of a lot of sense. Unlocking a CSD that is not locked is *wrong*.

The crazy code code comes from commit c84a83e2aaab ("smp: don't warn about csd->flags having CSD_FLAG_LOCK cleared for !wait") by Jens, but the explanation and the code is pure crap.

There is no way in hell that it is ever correct to unlock an entry that isn't locked, so that whole CSD_FLAG_WAIT thing is buggy as hell.

Quoted 7 lines

The explanation in commit c84a83e2aaab says that "blk-mq reuses the request potentially immediately" and claims that that is somehow ok, but that's utter BS. Even if you don't ever wait for it, the CSD lock bit fundamentally also protects the "csd->llist" pointer. So what that commit actually does is to just remove a safety check, and do so in a very unsafe manner. And apparently block-mq re-uses something THAT IS STILL ACTIVELY IN USE. That's just horrible.

I agree that this description is probably utter crap. And now I do actually remember the issue at hand. The resource here is the tag, that decides what request we'll use, and subsequently what call_single_data storage is used. When this was originally done, blk-mq cleared the request from the function callback, instead of doing it at allocation time. The assumption here was cache hotness. That in turn also cleared ->csd, which meant that the flags got zeroed and csd_unlock() was naturally unhappy.

THAT was the reuse case, not that the request would get reused before we had finished the IPI fn callback since that would obviously create other badness. Now I'm not sure what made me create that patch, which in retrospect is a bad hammer for this problem.

blk-mq doesn't do the init-at-finish time anymore, so it should not be hit by the issue. But if we do bring that back, then it would still work fine with Thomas' patch, since we unlock prior to running the callback.

Quoted 2 lines

No, that won't work for synchronous calls:\

So a combo of both (Jens and yours) might do the trick. Patch below.

Quoted 1 line · Thomas Gleixner

So a combo of both (Jens and yours) might do the trick. Patch below.

Yeah, I guess that would work. The important part is that *if* somebody really reuses the csd, we'd better have a release barrier (which csd_unlock() does, although badly - but this probably isn't that performance-critical) *before* we call the function, because otherwise there's no real serialization for the reuse.

Of course, most of these things are presumably always per-cpu data structures, so the whole worry about "csd" being accessed from different CPU's probably doesn't even exist, and this all works fine as-is anyway, even in the presense of odd memory ordering issues.

Judging from Jens' later email, it looks like we simply don't need this code at all any more, though, and we could just revert the commit.

NOTE! I don't think this actually has anything to do with the actual problem that Dave saw. I just reacted to that WARN_ON() when I was looking at the code, and it made me go "that looks extremely suspicious".

Particularly on x86, with strong memory ordering, I don't think that any random accesses to 'csd' after the call to 'csd->func()' could actually matter. I just felt very nervous about the claim that somebody can reuse the csd immediately, that smelled bad to me from a *conceptual* standpoint, even if I suspect it works perfectly fine in practice.

Anyway, I've found *another* race condition, which (again) doesn't actually seem to be an issue on x86.

In particular, "csd_lock()" does things pretty well, in that it does a smp_mb() after setting the lock bit, so certainly nothing afterwards will leak out of that locked region.

But look at csd_lock_wait(). It just does

        while (csd->flags & CSD_FLAG_LOCK)
                cpu_relax();

and basically there's no memory barriers there. Now, on x86, this is a non-issue, since all reads act as an acquire, but at least in *theory* we have this completely unordered read going on. So any subsequent memory oeprations (ie after the return from generic_exec_single() could in theory see data from *before* the read.

So that whole kernel/smp.c locking looks rather dubious. The smp_mb() in csd_lock() is overkill (a "smp_store_release()" should be sufficient), and I think that the read of csd->flags in csd_unlock() should be a smp_load_acquire().

Again, none of this has anything to do with Dave's problem. The memory ordering issues really cannot be an issue on x86, I'm just saying that there's code there that makes me a bit uncomfortable.

Quoted 8 lines · Dave Jones

It could a completely different cause for lockup, but seeing this now has me wondering if perhaps it's something unrelated to the kernel. I have recollection of running late .17rc's for days without incident, and I'm pretty sure .17 was ok too. But a few weeks ago I did upgrade that test box to the Fedora 21 beta. Which means I have a new gcc. I'm not sure I really trust 4.9.1 yet, so maybe I'll see if I can get 4.8 back on there and see if that's any better.

I'm not sure if I should be relieved or horrified.

Horrified, I think.

It really would be a wonderful thing to have some kind of "compiler bisection" with mixed object files to see exactly which file it miscompiles (and by "miscompiles" it might just be a kernel bug where we are missing a barrier or something, and older gcc's just happened to not show it - so it could still easily be a kernel problem).

After wasting countless hours rolling back to Fedora 20 and gcc 4.8.1, I saw the exact same trace on 3.17, so now I don't know what to think.

Quoted 30 lines · Jens Axboe

Quoted 21 lines · Linus Torvalds

Quoted 3 lines · Linus Torvalds

Judging by the code disassembly, it's the "csd_lock_wait(csd)" at the end.

Btw, looking at this, I grew really suspicious of this code in csd_unlock():

         WARN_ON((csd->flags & CSD_FLAG_WAIT) && !(csd->flags & CSD_FLAG_LOCK));

because that makes no sense at all. It basically removes a sanity check, yet that sanity check makes a hell of a lot of sense. Unlocking a CSD that is not locked is *wrong*.

The crazy code code comes from commit c84a83e2aaab ("smp: don't warn about csd->flags having CSD_FLAG_LOCK cleared for !wait") by Jens, but the explanation and the code is pure crap.

There is no way in hell that it is ever correct to unlock an entry that isn't locked, so that whole CSD_FLAG_WAIT thing is buggy as hell.

Quoted 7 lines

The explanation in commit c84a83e2aaab says that "blk-mq reuses the request potentially immediately" and claims that that is somehow ok, but that's utter BS. Even if you don't ever wait for it, the CSD lock bit fundamentally also protects the "csd->llist" pointer. So what that commit actually does is to just remove a safety check, and do so in a very unsafe manner. And apparently block-mq re-uses something THAT IS STILL ACTIVELY IN USE. That's just horrible.

Quoted 8 lines

I agree that this description is probably utter crap. And now I do actually remember the issue at hand. The resource here is the tag, that decides what request we'll use, and subsequently what call_single_data storage is used. When this was originally done, blk-mq cleared the request from the function callback, instead of doing it at allocation time. The assumption here was cache hotness. That in turn also cleared ->csd, which meant that the flags got zeroed and csd_unlock() was naturally unhappy.

So that's exactly what I described in my other reply.

      csd_lock(csd);
      queue_csd();
      ipi();
				csd->func(csd->info);
      wait_for_completion(csd);
				  complete(csd);
      reuse_csd(csd);		
				csd_unlock(csd);

When you call complete() nothing can rely on csd anymore, except for the smp core code ....

Quoted 4 lines

THAT was the reuse case, not that the request would get reused before we had finished the IPI fn callback since that would obviously create other badness. Now I'm not sure what made me create that patch, which in retrospect is a bad hammer for this problem.

Performance blindness?

Quoted 3 lines

blk-mq doesn't do the init-at-finish time anymore, so it should not be hit by the issue. But if we do bring that back, then it would still work fine with Thomas' patch, since we unlock prior to running the callback.

So if blk-mq is not relying on that, then we really should back out that stuff for 3.18 and tag it for stable.

Treating sync and async function calls differently makes sense, because any async caller which cannot deal with the unlock before call scheme is broken by definition already today. But that's material for next.

Quoted 3 lines · Dave Jones

After wasting countless hours rolling back to Fedora 20 and gcc 4.8.1, I saw the exact same trace on 3.17, so now I don't know what to think.

Uhhuh.

Has anything else changed? New trinity tests? If it has happened in as little as ten minutes, and you don't recall having seen this until about a week ago, it does sound like something changed.

So it could be that I'm just generating a lot more load now. I could drop that back down and see if it 'goes away' or at least happens less, but it strikes me that there's something here that needs fixing regardless.

Quoted 5 lines · Dave Jones

So it could be that I'm just generating a lot more load now. I could drop that back down and see if it 'goes away' or at least happens less, but it strikes me that there's something here that needs fixing regardless.

Oh, absolutely. It's more a question of "maybe what changed can give us a clue".

But if it' something like "more load", that's not going to help pinpoint, and you might be better off just doing the all-cpu-backtrace thing and hope that gives some pattern to appreciate..

Here's the first hit. Curiously, one cpu is missing.

NMI watchdog: BUG: soft lockup - CPU#1 stuck for 23s! [trinity-c180:17837]

RIP: 0010:[<ffffffffa91a0db0>]  [<ffffffffa91a0db0>] bad_range+0x0/0x90

Call Trace:
 [<ffffffffa91a6030>] __alloc_pages_nodemask+0x230/0xd20
 [<ffffffffa91f400e>] alloc_pages_vma+0xee/0x1b0
 [<ffffffffa91b643e>] shmem_alloc_page+0x6e/0xc0
 [<ffffffffa91b8ff0>] shmem_getpage_gfp+0x630/0xa40

 [<ffffffffa91b9442>] shmem_write_begin+0x42/0x70
 [<ffffffffa919a684>] generic_perform_write+0xd4/0x1f0
 [<ffffffffa919d5d2>] __generic_file_write_iter+0x162/0x350
 [<ffffffffa919d7ff>] generic_file_write_iter+0x3f/0xb0
 [<ffffffffa92155e8>] do_iter_readv_writev+0x78/0xc0
 [<ffffffffa9216e18>] do_readv_writev+0xd8/0x2a0
 [<ffffffffa90cf426>] ? lock_release_holdtime.part.28+0xe6/0x160
 [<ffffffffa921706c>] vfs_writev+0x3c/0x50

NMI backtrace for cpu 2

RIP: 0010:[<ffffffffa9116dbe>]  [<ffffffffa9116dbe>] generic_exec_single+0xee/0x1a0
Call Trace:
 [<ffffffffa9045bb0>] ? do_flush_tlb_all+0x60/0x60
 [<ffffffffa9116f3a>] smp_call_function_single+0x6a/0xe0
 [<ffffffffa9117679>] smp_call_function_many+0x2b9/0x320
 [<ffffffffa9046370>] flush_tlb_mm_range+0xe0/0x370
 [<ffffffffa91cc762>] tlb_flush_mmu_tlbonly+0x42/0x50
 [<ffffffffa91cdd28>] unmap_single_vma+0x6b8/0x900
 [<ffffffffa91ce06c>] zap_page_range_single+0xfc/0x160
 [<ffffffffa91ce254>] unmap_mapping_range+0x134/0x190

NMI backtrace for cpu 0

RIP: 0010:[<ffffffffa90ac450>]  [<ffffffffa90ac450>] preempt_count_add+0x0/0xc0
Call Trace:
 [<ffffffffa96bbb45>] cpuidle_enter_state+0x55/0x300
 [<ffffffffa96bbea7>] cpuidle_enter+0x17/0x20
 [<ffffffffa90c88f5>] cpu_startup_entry+0x4e5/0x630
 [<ffffffffa902d523>] start_secondary+0x1a3/0x220

INFO: NMI handler (arch_trigger_all_cpu_backtrace_handler) took too long to run: 125.739 msecs

Here's the first hit. Curiously, one cpu is missing.

NMI watchdog: BUG: soft lockup - CPU#1 stuck for 23s! [trinity-c180:17837]

irq event stamp: 2258092
hardirqs last  enabled at (2258091): [<ffffffffa91a58b5>] get_page_from_freelist+0x555/0xaa0
hardirqs last disabled at (2258092): [<ffffffffa985396a>] apic_timer_interrupt+0x6a/0x80

CPU: 1 PID: 17837 Comm: trinity-c180 Not tainted 3.18.0-rc5+ #90 [loadavg: 199.00 178.81 173.92 35/402 20526]
task: ffff8801575e4680 ti: ffff880202434000 task.ti: ffff880202434000
RIP: 0010:[<ffffffffa91a0db0>]  [<ffffffffa91a0db0>] bad_range+0x0/0x90

sending NMI to other CPUs:

NMI backtrace for cpu 2

CPU: 2 PID: 15913 Comm: trinity-c141 Not tainted 3.18.0-rc5+ #90 [loadavg: 199.00 178.81 173.92 35/402 20526]
task: ffff880223229780 ti: ffff8801afca0000 task.ti: ffff8801afca0000
RIP: 0010:[<ffffffffa9116dbe>]  [<ffffffffa9116dbe>] generic_exec_single+0xee/0x1a0
 [<ffffffffa9045bb0>] ? do_flush_tlb_all+0x60/0x60
 [<ffffffffa9045bb0>] ? do_flush_tlb_all+0x60/0x60
 [<ffffffffa9116f3a>] smp_call_function_single+0x6a/0xe0
 [<ffffffffa93b2e1f>] ? cpumask_next_and+0x4f/0xb0
 [<ffffffffa9045bb0>] ? do_flush_tlb_all+0x60/0x60
 [<ffffffffa9117679>] smp_call_function_many+0x2b9/0x320
 [<ffffffffa9046370>] flush_tlb_mm_range+0xe0/0x370
 [<ffffffffa91cc762>] tlb_flush_mmu_tlbonly+0x42/0x50
 [<ffffffffa91cdd28>] unmap_single_vma+0x6b8/0x900
 [<ffffffffa91ce06c>] zap_page_range_single+0xfc/0x160

 [<ffffffffa91ce254>] unmap_mapping_range+0x134/0x190
 [<ffffffffa91bb9dd>] shmem_fallocate+0x4fd/0x520
 [<ffffffffa90c7c77>] ? prepare_to_wait+0x27/0x90
 [<ffffffffa9213bc2>] do_fallocate+0x132/0x1d0
 [<ffffffffa91e3228>] SyS_madvise+0x398/0x870
 [<ffffffffa983f6c0>] ? rcu_read_lock_sched_held+0x4e/0x6a
 [<ffffffffa9013877>] ? syscall_trace_enter_phase2+0xa7/0x2b0
 [<ffffffffa9852c49>] tracesys_phase2+0xd4/0xd9

NMI backtrace for cpu 0
INFO: NMI handler (arch_trigger_all_cpu_backtrace_handler) took too long to run: 37.091 msecs

CPU: 0 PID: 15851 Comm: trinity-c80 Not tainted 3.18.0-rc5+ #90 [loadavg: 199.00 178.81 173.92 36/402 20526]
task: ffff8801874e8000 ti: ffff88022baec000 task.ti: ffff88022baec000
RIP: 0010:[<ffffffffa90ac450>]  [<ffffffffa90ac450>] preempt_count_add+0x0/0xc0
RSP: 0000:ffff880244003c30  EFLAGS: 00000092
RAX: 0000000000000001 RBX: ffffffffa9edb560 RCX: 0000000000000001
RDX: 0000000000000001 RSI: 0000000000000001 RDI: 0000000000000001
RBP: ffff880244003c48 R08: 0000000000000000 R09: 0000000000000001
R10: 0000000000000000 R11: ffff8801874e88c8 [23543.271956] NMI backtrace for cpu 3

INFO: NMI handler (arch_trigger_all_cpu_backtrace_handler) took too long to run: 100.612 msecs

CPU: 3 PID: 0 Comm: swapper/3 Not tainted 3.18.0-rc5+ #90 [loadavg: 199.00 178.81 173.92 37/402 20526]
task: ffff880242b5c680 ti: ffff880242b78000 task.ti: ffff880242b78000
RIP: 0010:[<ffffffffa94251b5>]  [<ffffffffa94251b5>] intel_idle+0xd5/0x180

INFO: NMI handler (arch_trigger_all_cpu_backtrace_handler) took too long to run: 125.739 msecs

Quoted 2 lines · Dave Jones

Here's the first hit. Curiously, one cpu is missing.

That might be the CPU3 that isn't responding to IPIs due to some bug..

Quoted 2 lines

NMI watchdog: BUG: soft lockup - CPU#1 stuck for 23s! [trinity-c180:17837]

RIP: 0010:[<ffffffffa91a0db0>]  [<ffffffffa91a0db0>] bad_range+0x0/0x90

Hmm. Something looping in the page allocator? Not waiting for a lock, but livelocked? I'm not seeing anything here that should trigger the NMI watchdog at all.

Can the NMI watchdog get confused somehow?

So it does look like CPU3 is the problem, but sadly, CPU3 is apparently not listening, and doesn't even react to the NMI, much less

Quoted 6 lines · Linus Torvalds

Quoted 2 lines · Dave Jones

Here's the first hit. Curiously, one cpu is missing.

That might be the CPU3 that isn't responding to IPIs due to some bug..

Quoted 8 lines

Quoted 2 lines

NMI watchdog: BUG: soft lockup - CPU#1 stuck for 23s! [trinity-c180:17837]

RIP: 0010:[<ffffffffa91a0db0>]  [<ffffffffa91a0db0>] bad_range+0x0/0x90

Hmm. Something looping in the page allocator? Not waiting for a lock, but livelocked? I'm not seeing anything here that should trigger the NMI watchdog at all.

Can the NMI watchdog get confused somehow?

That's the soft lockup detector which runs from the timer interrupt not from NMI.

Quoted 2 lines

So it does look like CPU3 is the problem, but sadly, CPU3 is apparently not listening, and doesn't even react to the NMI, much less

As I said in the other mail. It gets the NMI and reacts on it. It's just mangled into the CPU0 backtrace.

I was going to reply about both points too. :-) Though the mangling looks odd because we have spin_locks serializing the output for each cpu.

Another thing I wanted to ask DaveJ, did you recently turn on CONFIG_PREEMPT? That would explain why you are seeing the softlockups now. If you disable CONFIG_PREEMPT does the softlockups disappear.

Quoted 1 line · Dave Jones

Here's the first hit. Curiously, one cpu is missing.

I don't think so

Quoted 5 lines

NMI watchdog: BUG: soft lockup - CPU#1 stuck for 23s! [trinity-c180:17837]

irq event stamp: 2258092
hardirqs last  enabled at (2258091): [<ffffffffa91a58b5>] get_page_from_freelist+0x555/0xaa0
hardirqs last disabled at (2258092): [<ffffffffa985396a>] apic_timer_interrupt+0x6a/0x80

So that means we are in the timer interrupt and handling watchdog_timer_fn.

Quoted 3 lines

CPU: 1 PID: 17837 Comm: trinity-c180 Not tainted 3.18.0-rc5+ #90 [loadavg: 199.00 178.81 173.92 35/402 20526]
task: ffff8801575e4680 ti: ffff880202434000 task.ti: ffff880202434000
RIP: 0010:[<ffffffffa91a0db0>]  [<ffffffffa91a0db0>] bad_range+0x0/0x90

So the softlockup tells us, that the high priority watchdog thread was not able to touch the watchdog timestamp. That means this task was hogging the CPU for 20+ seconds. I have no idea how that happens in that call chain.

Call Trace:
 [<ffffffffa91a58c4>] ? get_page_from_freelist+0x564/0xaa0
 [<ffffffffa90ac411>] ? get_parent_ip+0x11/0x50
 [<ffffffffa91a6030>] __alloc_pages_nodemask+0x230/0xd20
 [<ffffffffa90ac411>] ? get_parent_ip+0x11/0x50
 [<ffffffffa90d1e45>] ? mark_held_locks+0x75/0xa0
 [<ffffffffa91f400e>] alloc_pages_vma+0xee/0x1b0
 [<ffffffffa91b643e>] ? shmem_alloc_page+0x6e/0xc0
 [<ffffffffa91b643e>] shmem_alloc_page+0x6e/0xc0
 [<ffffffffa90ac411>] ? get_parent_ip+0x11/0x50
 [<ffffffffa90ac58b>] ? preempt_count_sub+0x7b/0x100
 [<ffffffffa93dcc46>] ? __percpu_counter_add+0x86/0xb0
 [<ffffffffa91d50d6>] ? __vm_enough_memory+0x66/0x1c0
 [<ffffffffa919ad65>] ? find_get_entry+0x5/0x230
 [<ffffffffa933b10c>] ? cap_vm_enough_memory+0x4c/0x60
 [<ffffffffa91b8ff0>] shmem_getpage_gfp+0x630/0xa40
 [<ffffffffa90cee01>] ? match_held_lock+0x111/0x160
 [<ffffffffa91b9442>] shmem_write_begin+0x42/0x70
 [<ffffffffa919a684>] generic_perform_write+0xd4/0x1f0
 [<ffffffffa919d5d2>] __generic_file_write_iter+0x162/0x350
 [<ffffffffa92154a0>] ? new_sync_read+0xd0/0xd0
 [<ffffffffa919d7ff>] generic_file_write_iter+0x3f/0xb0
 [<ffffffffa919d7c0>] ? __generic_file_write_iter+0x350/0x350
 [<ffffffffa92155e8>] do_iter_readv_writev+0x78/0xc0
 [<ffffffffa9216e18>] do_readv_writev+0xd8/0x2a0
 [<ffffffffa919d7c0>] ? __generic_file_write_iter+0x350/0x350
 [<ffffffffa90cf426>] ? lock_release_holdtime.part.28+0xe6/0x160
 [<ffffffffa919d7c0>] ? __generic_file_write_iter+0x350/0x350
 [<ffffffffa90ac411>] ? get_parent_ip+0x11/0x50
 [<ffffffffa90ac58b>] ? preempt_count_sub+0x7b/0x100
 [<ffffffffa90e782e>] ? rcu_read_lock_held+0x6e/0x80
 [<ffffffffa921706c>] vfs_writev+0x3c/0x50
 [<ffffffffa92171dc>] SyS_writev+0x5c/0x100
 [<ffffffffa9852c49>] tracesys_phase2+0xd4/0xd9

But this gets pages for a write into shmem and the other one below does a madvise on a shmem map. Coincidence?

Quoted 1 line

sending NMI to other CPUs:

So here we kick the other cpus

Quoted 14 lines

NMI backtrace for cpu 2

CPU: 2 PID: 15913 Comm: trinity-c141 Not tainted 3.18.0-rc5+ #90 [loadavg: 199.00 178.81 173.92 35/402 20526]
task: ffff880223229780 ti: ffff8801afca0000 task.ti: ffff8801afca0000
RIP: 0010:[<ffffffffa9116dbe>]  [<ffffffffa9116dbe>] generic_exec_single+0xee/0x1a0
 [<ffffffffa9045bb0>] ? do_flush_tlb_all+0x60/0x60
 [<ffffffffa9045bb0>] ? do_flush_tlb_all+0x60/0x60
 [<ffffffffa9116f3a>] smp_call_function_single+0x6a/0xe0
 [<ffffffffa93b2e1f>] ? cpumask_next_and+0x4f/0xb0
 [<ffffffffa9045bb0>] ? do_flush_tlb_all+0x60/0x60
 [<ffffffffa9117679>] smp_call_function_many+0x2b9/0x320
 [<ffffffffa9046370>] flush_tlb_mm_range+0xe0/0x370
 [<ffffffffa91cc762>] tlb_flush_mmu_tlbonly+0x42/0x50
 [<ffffffffa91cdd28>] unmap_single_vma+0x6b8/0x900
 [<ffffffffa91ce06c>] zap_page_range_single+0xfc/0x160

Quoted 8 lines

 [<ffffffffa91ce254>] unmap_mapping_range+0x134/0x190
 [<ffffffffa91bb9dd>] shmem_fallocate+0x4fd/0x520
 [<ffffffffa90c7c77>] ? prepare_to_wait+0x27/0x90
 [<ffffffffa9213bc2>] do_fallocate+0x132/0x1d0
 [<ffffffffa91e3228>] SyS_madvise+0x398/0x870
 [<ffffffffa983f6c0>] ? rcu_read_lock_sched_held+0x4e/0x6a
 [<ffffffffa9013877>] ? syscall_trace_enter_phase2+0xa7/0x2b0
 [<ffffffffa9852c49>] tracesys_phase2+0xd4/0xd9

We've seen that before

Quoted 2 lines

NMI backtrace for cpu 0
INFO: NMI handler (arch_trigger_all_cpu_backtrace_handler) took too long to run: 37.091 msecs

So it complains that the backtrace handler took 37 msec, which is indeed long for just dumping a stack trace.

Quoted 8 lines

CPU: 0 PID: 15851 Comm: trinity-c80 Not tainted 3.18.0-rc5+ #90 [loadavg: 199.00 178.81 173.92 36/402 20526]
task: ffff8801874e8000 ti: ffff88022baec000 task.ti: ffff88022baec000
RIP: 0010:[<ffffffffa90ac450>]  [<ffffffffa90ac450>] preempt_count_add+0x0/0xc0
RSP: 0000:ffff880244003c30  EFLAGS: 00000092
RAX: 0000000000000001 RBX: ffffffffa9edb560 RCX: 0000000000000001
RDX: 0000000000000001 RSI: 0000000000000001 RDI: 0000000000000001
RBP: ffff880244003c48 R08: 0000000000000000 R09: 0000000000000001
R10: 0000000000000000 R11: ffff8801874e88c8 [23543.271956] NMI backtrace for cpu 3

So here we mangle CPU3 in and lose the backtrace for cpu0, which might be the real interesting one ....

Quoted 2 lines

INFO: NMI handler (arch_trigger_all_cpu_backtrace_handler) took too long to run: 100.612 msecs

This one takes 100ms.

Quoted 3 lines

CPU: 3 PID: 0 Comm: swapper/3 Not tainted 3.18.0-rc5+ #90 [loadavg: 199.00 178.81 173.92 37/402 20526]
task: ffff880242b5c680 ti: ffff880242b78000 task.ti: ffff880242b78000
RIP: 0010:[<ffffffffa94251b5>]  [<ffffffffa94251b5>] intel_idle+0xd5/0x180

So that one is simply idle.

Quoted 2 lines

INFO: NMI handler (arch_trigger_all_cpu_backtrace_handler) took too long to run: 125.739 msecs

And we get another backtrace handler taking too long. Of course we cannot tell which of the 3 complaints comes from which cpu, because the printk lacks a cpuid.

Thanks,

tglx

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/

Quoted 2 lines

So here we mangle CPU3 in and lose the backtrace for cpu0, which might be the real interesting one ....

Can you provide another dump? The hope is we get something not mangled?

The other option we have done in RHEL is panic the system and let kdump capture the memory. Then we can analyze the vmcore for the stack trace cpu0 stored in memory to get a rough idea where it might be if the cpu isn't responding very well.

Can you provide another dump? The hope is we get something not mangled?

NMI watchdog: BUG: soft lockup - CPU#2 stuck for 21s! [trinity-c42:31480]

CPU: 2 PID: 31480 Comm: trinity-c42 Not tainted 3.18.0-rc5+ #91 [loadavg: 174.61 150.35 148.64 9/411 32140]
RIP: 0010:[<ffffffff8a1798b4>]  [<ffffffff8a1798b4>] context_tracking_user_enter+0xa4/0x190
Call Trace:
 [<ffffffff8a012fc5>] syscall_trace_leave+0xa5/0x160
 [<ffffffff8a7d8624>] int_check_syscall_exit_work+0x34/0x3d

CPU: 0 PID: 27716 Comm: kworker/0:1 Not tainted 3.18.0-rc5+ #91 [loadavg: 174.61 150.35 148.64 9/411 32140]
Workqueue: events nohz_kick_work_fn
RIP: 0010:[<ffffffff8a0ffb52>]  [<ffffffff8a0ffb52>] smp_call_function_many+0x1b2/0x320
Call Trace:
 [<ffffffff8a0fa3f5>] tick_nohz_full_kick_all+0x35/0x70
 [<ffffffff8a0ec8fe>] nohz_kick_work_fn+0xe/0x10
 [<ffffffff8a08e61d>] process_one_work+0x1fd/0x590
 [<ffffffff8a08eacb>] worker_thread+0x11b/0x490
 [<ffffffff8a0942e9>] kthread+0xf9/0x110
 [<ffffffff8a7d82ac>] ret_from_fork+0x7c/0xb0

CPU: 1 PID: 0 Comm: swapper/1 Not tainted 3.18.0-rc5+ #91 [loadavg: 174.61 150.35 148.64 10/411 32140]
RIP: 0010:[<ffffffff8a3e14a5>]  [<ffffffff8a3e14a5>] intel_idle+0xd5/0x180
Call Trace:
 [<ffffffff8a666075>] cpuidle_enter_state+0x55/0x1c0
 [<ffffffff8a666297>] cpuidle_enter+0x17/0x20
 [<ffffffff8a0bb323>] cpu_startup_entry+0x433/0x4e0
 [<ffffffff8a02b763>] start_secondary+0x1a3/0x220

CPU: 3 PID: 0 Comm: swapper/3 Not tainted 3.18.0-rc5+ #91 [loadavg: 174.61 150.35 148.64 10/411 32140]
RIP: 0010:[<ffffffff8a3e14a5>]  [<ffffffff8a3e14a5>] intel_idle+0xd5/0x180
 [<ffffffff8a666075>] cpuidle_enter_state+0x55/0x1c0
 [<ffffffff8a666297>] cpuidle_enter+0x17/0x20
 [<ffffffff8a0bb323>] cpu_startup_entry+0x433/0x4e0
 [<ffffffff8a02b763>] start_secondary+0x1a3/0x220

Quoted 7 lines · Dave Jones

NMI watchdog: BUG: soft lockup - CPU#2 stuck for 21s! [trinity-c42:31480]

CPU: 2 PID: 31480 Comm: trinity-c42 Not tainted 3.18.0-rc5+ #91 [loadavg: 174.61 150.35 148.64 9/411 32140]
RIP: 0010:[<ffffffff8a1798b4>]  [<ffffffff8a1798b4>] context_tracking_user_enter+0xa4/0x190
Call Trace:
 [<ffffffff8a012fc5>] syscall_trace_leave+0xa5/0x160
 [<ffffffff8a7d8624>] int_check_syscall_exit_work+0x34/0x3d

Hmm, if we are getting soft-lockups here, maybe it suggest too much exit-work.

Some TIF_NOHZ loop, perhaps? You have nohz on, don't you?

That makes me wonder: does the problem go away if you disable NOHZ?

Hmm, if we are getting soft-lockups here, maybe it suggest too much exit-work.

Some TIF_NOHZ loop, perhaps? You have nohz on, don't you?

That makes me wonder: does the problem go away if you disable NOHZ?

Quoted 4 lines · Don Zickus

Quoted 2 lines

So here we mangle CPU3 in and lose the backtrace for cpu0, which might be the real interesting one ....

Can you provide another dump? The hope is we get something not mangled?

Working on it..

Quoted 4 lines

The other option we have done in RHEL is panic the system and let kdump capture the memory. Then we can analyze the vmcore for the stack trace cpu0 stored in memory to get a rough idea where it might be if the cpu isn't responding very well.

I don't know if it's because of the debug options I typically run with, or that I'm perpetually cursed, but I've never managed to get kdump to do anything useful. (The last time I tried it was actively harmful in that not only did it fail to dump anything, it wedged the machine so it didn't reboot after panic).

Unless there's some magic step missing from the documentation at
http://fedoraproject.org/wiki/How_to_use_kdump_to_debug_kernel_crashes
then I'm not optimistic it'll be useful.

Quoted 7 lines · Dave Jones

NMI watchdog: BUG: soft lockup - CPU#2 stuck for 21s! [trinity-c42:31480]

CPU: 2 PID: 31480 Comm: trinity-c42 Not tainted 3.18.0-rc5+ #91 [loadavg: 174.61 150.35 148.64 9/411 32140]
RIP: 0010:[<ffffffff8a1798b4>]  [<ffffffff8a1798b4>] context_tracking_user_enter+0xa4/0x190
Call Trace:
 [<ffffffff8a012fc5>] syscall_trace_leave+0xa5/0x160
 [<ffffffff8a7d8624>] int_check_syscall_exit_work+0x34/0x3d

Hmm, if we are getting soft-lockups here, maybe it suggest too much exit-work.

Some TIF_NOHZ loop, perhaps? You have nohz on, don't you?

That makes me wonder: does the problem go away if you disable NOHZ?

Quoted 14 lines · Dave Jones

Quoted 4 lines · Don Zickus

Quoted 2 lines

So here we mangle CPU3 in and lose the backtrace for cpu0, which might be the real interesting one ....

Can you provide another dump? The hope is we get something not mangled?

Working on it..

Quoted 4 lines

The other option we have done in RHEL is panic the system and let kdump capture the memory. Then we can analyze the vmcore for the stack trace cpu0 stored in memory to get a rough idea where it might be if the cpu isn't responding very well.

Quoted 5 lines

I don't know if it's because of the debug options I typically run with, or that I'm perpetually cursed, but I've never managed to get kdump to do anything useful. (The last time I tried it was actively harmful in that not only did it fail to dump anything, it wedged the machine so it didn't reboot after panic).

Quoted 4 lines

Unless there's some magic step missing from the documentation at
http://fedoraproject.org/wiki/How_to_use_kdump_to_debug_kernel_crashes
then I'm not optimistic it'll be useful.

Well, I don't know when the last time you ran it, but I know the RH kexec folks have started pursuing a Fedora-first package patch rule a couple of years ago to ensure Fedora had a working kexec/kdump solution.

As for the wedging part, it was a common problem to have the kernel hang while trying to boot the second kernel (and before console output happened). So the problem makes sense and is unfortunate. I would encourage you to try again. :-)

Though, it is transitioning to have the app built into the kernel to deal with the whole secure boot thing, so that might be another can of worms.

Not being able to capture the dump I can understand but having wedged the machine so that it does not reboot after dump failure sounds bad. So you could not get machine to boot even after a power cycle? Would you remember what was failing. I am curious to know what did kdump do to make machine unbootable.

Quoted 3 lines

Quoted 3 lines

Unless there's some magic step missing from the documentation at
http://fedoraproject.org/wiki/How_to_use_kdump_to_debug_kernel_crashes
then I'm not optimistic it'll be useful.

I had a quick look at it and it basically looks fine. In fedora ideally it is just two steps process.

- Reserve memory using crashkernel. Say crashkernel=160M
- systemctl start kdump
- Crash the system or wait for it to crash.

So despite your bad experience in the past, I would encourage you to give it a try.

Quoted 5 lines · Vivek Goyal

Not being able to capture the dump I can understand but having wedged the machine so that it does not reboot after dump failure sounds bad. So you could not get machine to boot even after a power cycle? Would you remember what was failing. I am curious to know what did kdump do to make machine unbootable.

Power cycling was fine, because then it booted into the non-kdump kernel. The issue was when I caused that kernel to panic, it would just sit there wedged, with no indication it even tried to switch to the kdump kernel.

Quoted 8 lines

Quoted 4 lines

Quoted 4 lines

Unless there's some magic step missing from the documentation at
http://fedoraproject.org/wiki/How_to_use_kdump_to_debug_kernel_crashes
then I'm not optimistic it'll be useful.

I had a quick look at it and it basically looks fine. In fedora ideally it is just two steps process.

Quoted 6 lines

- Reserve memory using crashkernel. Say crashkernel=160M
- systemctl start kdump
- Crash the system or wait for it to crash.

So despite your bad experience in the past, I would encourage you to give it a try.

'the past' here, is two weeks ago, on Fedora 21.

But, since then, I've reinstalled that box with Fedora 20 because I didn't trust gcc 4.9, and on f20 things are actually even worse.

Right now it doesn't even create the image correctly:

dracut: *** Stripping files done ***
dracut: *** Store current command line parameters ***
dracut: *** Creating image file ***
dracut: *** Creating image file done ***
kdumpctl: cat: write error: Broken pipe
kdumpctl: kexec: failed to load kdump kernel
kdumpctl: Starting kdump: [FAILED]

It works if I run a Fedora kernel, but not with a self-built one. And there's zero information as to what I'm doing wrong.

Quoted 2 lines · Linus Torvalds

That makes me wonder: does the problem go away if you disable NOHZ?

Aparently not.

NMI watchdog: BUG: soft lockup - CPU#3 stuck for 22s! [trinity-c75:25175]

CPU: 3 PID: 25175 Comm: trinity-c75 Not tainted 3.18.0-rc5+ #92 [loadavg: 168.72 151.72 150.38 9/410 27945]
RIP: 0010:[<ffffffff94175be7>]  [<ffffffff94175be7>] context_tracking_user_exit+0x57/0x120
Call Trace:
 [<ffffffff94012c25>] syscall_trace_enter_phase1+0x125/0x1a0
 [<ffffffff9437b3be>] ? trace_hardirqs_on_thunk+0x3a/0x3f
 [<ffffffff947d41bf>] tracesys+0x14/0x4a

CPU: 1 PID: 25164 Comm: trinity-c64 Not tainted 3.18.0-rc5+ #92 [loadavg: 168.72 151.72 150.38 9/410 27945]
RIP: 0010:[<ffffffff940fb71e>]  [<ffffffff940fb71e>] generic_exec_single+0xee/0x1a0
Call Trace:
 [<ffffffff940fb89a>] smp_call_function_single+0x6a/0xe0
 [<ffffffff941671aa>] perf_event_read+0xca/0xd0
 [<ffffffff94167240>] perf_event_read_value+0x90/0xe0
 [<ffffffff941689c6>] perf_read+0x226/0x370
 [<ffffffff941eafff>] vfs_read+0x9f/0x180

CPU: 0 PID: 0 Comm: swapper/0 Not tainted 3.18.0-rc5+ #92 [loadavg: 168.72 151.72 150.38 11/410 27945]
RIP: 0010:[<ffffffff943dd415>]  [<ffffffff943dd415>] intel_idle+0xd5/0x180
CPU: 2 PID: 0 Comm: swapper/2 Not tainted 3.18.0-rc5+ #92 [loadavg: 168.72 151.72 150.38 10/410 27945]
RIP: 0010:[<ffffffff943dd415>]  [<ffffffff943dd415>] intel_idle+0xd5/0x180

Also, today I learned we can reach the perf_event_read code from read(). Given I had /proc/sys/kernel/perf_event_paranoid set to 1, I'm not sure how this is even possible. The only user of perf_fops is perf_event_open syscall _after_ it's checked that sysctl.

Oh, there's an ioctl path to perf too. Though trinity doesn't know anything about it, so I find it surprising if it managed to pull the right combination of entropy to make that do the right thing. Still, that ioctl path probably needs to also be checking that sysctl shouldn't it ?

So it hasn't actually done the "push %rbx; popfq" part - there must be a label at the return part, and context_tracking_user_exit() never actually did the local_irq_save/restore at all. Which means that it took one of the early exits instead:

        if (!context_tracking_is_enabled())
                return;

        if (in_interrupt())
                return;

Quoted 11 lines · Linus Torvalds

So it hasn't actually done the "push %rbx; popfq" part - there must be a label at the return part, and context_tracking_user_exit() never actually did the local_irq_save/restore at all. Which means that it took one of the early exits instead:

        if (!context_tracking_is_enabled())
                return;

        if (in_interrupt())
                return;

Ho humm. Interesting. Neither of those should possibly have happened.

We "know" that "context_tracking_is_enabled()" must be true, because the only way we get to context_tracking_user_exit() in the first place is through "user_exit()", which does:

        if (context_tracking_is_enabled())
                context_tracking_user_exit();

and we know we shouldn't be in_interrupt(), because the backtrace is the system call entry path, for chrissake!

So we definitely have some corruption going on. A few possibilities:

- either the register contents are corrupted (%rbx in your dump said
"0x0000000100000046", but the eflags we restored was 0x246)

- in_interrupt() is wrong, and we've had some irq_count() corruption.
I'd expect that to result in "scheduling while atomic" messages, though, especially if it goes on long enough that you get a watchdog event..

- there is something rotten in the land of
context_tracking_is_enabled(), which uses a static key.

- I have misread the whole trace, and am a moron. But your earlier
report really had some very similar things, just in context_tracking_user_enter() instead of exit.

In your previous oops, the registers that was allegedly used to restore %eflags was %r12:

28: 41 54 push %r12
2a: 9d popfq

  2b:* 5b                   pop    %rbx <-- trapping instruction
  2c: 41 5c                 pop    %r12

2e: 5d pop %rbp
2f: c3 retq

but:

R12: ffff880101ee3ec0
EFLAGS: 00000282

so again, it looks like we never actually did that "popfq" instruction, and it would have exited through the (same) early exits.

But what an odd coincidence that it ended up in both of your reports being *exactly* at that instruction after the "popf". If it had actually *taken* the popf, I'd not be so surprised ("ok, popf enabled interrupts, and there was an interrupt pending"), but since everything seems to say that it came there through some control flow that did *not* go through the popf, that's just a very odd coincidence.

And both context_tracking_user_enter() and exit() have that exact same issue with the early returns. They shouldn't have happened in the first place.

Quoted 68 lines · Linus Torvalds

Quoted 11 lines · Linus Torvalds

So it hasn't actually done the "push %rbx; popfq" part - there must be a label at the return part, and context_tracking_user_exit() never actually did the local_irq_save/restore at all. Which means that it took one of the early exits instead:

        if (!context_tracking_is_enabled())
                return;

        if (in_interrupt())
                return;

Ho humm. Interesting. Neither of those should possibly have happened.

We "know" that "context_tracking_is_enabled()" must be true, because the only way we get to context_tracking_user_exit() in the first place is through "user_exit()", which does:

        if (context_tracking_is_enabled())
                context_tracking_user_exit();

and we know we shouldn't be in_interrupt(), because the backtrace is the system call entry path, for chrissake!

So we definitely have some corruption going on. A few possibilities:

- either the register contents are corrupted (%rbx in your dump said
"0x0000000100000046", but the eflags we restored was 0x246)

- in_interrupt() is wrong, and we've had some irq_count() corruption.
I'd expect that to result in "scheduling while atomic" messages, though, especially if it goes on long enough that you get a watchdog event..

- there is something rotten in the land of
context_tracking_is_enabled(), which uses a static key.

- I have misread the whole trace, and am a moron. But your earlier
report really had some very similar things, just in context_tracking_user_enter() instead of exit.

In your previous oops, the registers that was allegedly used to restore %eflags was %r12:

28: 41 54 push %r12
2a: 9d popfq

  2b:* 5b                   pop    %rbx <-- trapping instruction
  2c: 41 5c                 pop    %r12

2e: 5d pop %rbp
2f: c3 retq

but:

R12: ffff880101ee3ec0
EFLAGS: 00000282

so again, it looks like we never actually did that "popfq" instruction, and it would have exited through the (same) early exits.

But what an odd coincidence that it ended up in both of your reports being *exactly* at that instruction after the "popf". If it had actually *taken* the popf, I'd not be so surprised ("ok, popf enabled interrupts, and there was an interrupt pending"), but since everything seems to say that it came there through some control flow that did *not* go through the popf, that's just a very odd coincidence.

Quoted 3 lines

And both context_tracking_user_enter() and exit() have that exact same issue with the early returns. They shouldn't have happened in the first place.

I got a report lately involving context tracking. Not sure if it's the same here but the issue was that context tracking uses per cpu data and per cpu allocation use vmalloc and vmalloc'ed area can fault due to lazy paging.

Quoted 6 lines · Dave Jones

Quoted 2 lines · Linus Torvalds

That makes me wonder: does the problem go away if you disable NOHZ?

Aparently not.

Quoted 7 lines

NMI watchdog: BUG: soft lockup - CPU#3 stuck for 22s! [trinity-c75:25175]

CPU: 3 PID: 25175 Comm: trinity-c75 Not tainted 3.18.0-rc5+ #92 [loadavg: 168.72 151.72 150.38 9/410 27945]
RIP: 0010:[<ffffffff94175be7>]  [<ffffffff94175be7>] context_tracking_user_exit+0x57/0x120
Call Trace:
 [<ffffffff94012c25>] syscall_trace_enter_phase1+0x125/0x1a0
 [<ffffffff9437b3be>] ? trace_hardirqs_on_thunk+0x3a/0x3f
 [<ffffffff947d41bf>] tracesys+0x14/0x4a

Ok, that's just crazy. This is the system call *entry* portion.

Last time it was the system call exit side, which at least made some sense, because the "return to user space" thing actually has loops in it to handle all events before we return to user space.

But the whole 'tracesys' part is only entered once, at the very beginning of a system call. There's no loop over the work. That whole call trace implies that the lockup happened just after we entered the system call path from _user_ space.

And in fact, exactly like last time, the code line implies that the timer interrupt happened on the return from the instruction, and indeed in both cases the code looked like this (the registers differed, but the "restore flags, start popping saved regs" was the exact same):

26: 53 push %rbx
27: 9d popfq

  28:* 5b                   pop    %rbx <-- trapping instruction
  29: 41 5c                 pop    %r12

in both cases, the timer interrupt happened right after the "popfq", but in both cases the value in the register that was used to restore eflags was invalid. Here %rbx was 0x0000000100000046 (which is a valid eflags value, but not the one we've actually restored!), and in your previous oops (where it was %r12) it was completely invalid.

So it hasn't actually done the "push %rbx; popfq" part - there must be a label at the return part, and context_tracking_user_exit() never actually did the local_irq_save/restore at all. Which means that it took one of the early exits instead:

        if (!context_tracking_is_enabled())
                return;

        if (in_interrupt())
                return;

So not only does this happen at early system call entry time, the function that is claimed to lock up doesn't actually *do* anything.

Ho humm..

Oh, and to make matters worse, the only way this call chain can happen is this in syscall_trace_enter_phase1():

        if (work & _TIF_NOHZ) {
                user_exit();
                work &= ~TIF_NOHZ;
        }

so there's still some NOHZ confusion there. It looks like TIF_NOHZ gets set regardless of whether NOHZ is enabled or not..

I'm adding Frederic explicitly to the cc too, because this is just fishy. I am starting to blame context tracking, because it has now shown up twice in different guises, and TIF_NOHZ seems to be implicated.

Quoted 9 lines

CPU: 1 PID: 25164 Comm: trinity-c64 Not tainted 3.18.0-rc5+ #92 [loadavg: 168.72 151.72 150.38 9/410 27945]
RIP: 0010:[<ffffffff940fb71e>]  [<ffffffff940fb71e>] generic_exec_single+0xee/0x1a0
Call Trace:
 [<ffffffff940fb89a>] smp_call_function_single+0x6a/0xe0
 [<ffffffff941671aa>] perf_event_read+0xca/0xd0
 [<ffffffff94167240>] perf_event_read_value+0x90/0xe0
 [<ffffffff941689c6>] perf_read+0x226/0x370
 [<ffffffff941eafff>] vfs_read+0x9f/0x180

Hmm.. We've certainly seen a lot of smp_call, for various different reasons in your traces..

I'm wondering if the smp-call ended up corrupting something on CPU3. Because even _with_ TIF_NOHZ confusion, I don't see how system call *entry* could cause a watchdog event. There are no loops, there are no locks I see, there is just *nothing* there I can see.

Let's add Andy L to the cc too, in case he hasn't seen this. He's been changing the lowlevel asm code, including very much this whole "syscall_trace_enter_phase1" thing. Maybe he sees something I don't.

Andy?

Quoted 4 lines

CPU: 0 PID: 0 Comm: swapper/0 Not tainted 3.18.0-rc5+ #92 [loadavg: 168.72 151.72 150.38 11/410 27945]
RIP: 0010:[<ffffffff943dd415>]  [<ffffffff943dd415>] intel_idle+0xd5/0x180
CPU: 2 PID: 0 Comm: swapper/2 Not tainted 3.18.0-rc5+ #92 [loadavg: 168.72 151.72 150.38 10/410 27945]
RIP: 0010:[<ffffffff943dd415>]  [<ffffffff943dd415>] intel_idle+0xd5/0x180

Nothing there.

Quoted 10 lines

Also, today I learned we can reach the perf_event_read code from read(). Given I had /proc/sys/kernel/perf_event_paranoid set to 1, I'm not sure how this is even possible. The only user of perf_fops is perf_event_open syscall _after_ it's checked that sysctl.

Oh, there's an ioctl path to perf too. Though trinity doesn't know anything about it, so I find it surprising if it managed to pull the right combination of entropy to make that do the right thing. Still, that ioctl path probably needs to also be checking that sysctl shouldn't it ?

Hmm. Perf people are already mostly on the list. Peter/Ingo/Arnaldo?

Linus

I suspect that the regression was triggered by the seccomp pull, since that reworked a lot of this code.

Just to make sure I understand: it says "NMI watchdog", but this trace is from a timer interrupt, not NMI, right?

Is it possible that we've managed to return to userspace with interrupts off somehow? A loop in userspace that somehow has interrupts off can cause all kinds of fun lockups.

I don't understand the logic of what enables TIF_NOHZ.

In 3.17, I don't think that code would run with context tracking on, although I don't immediately see any bugs here.

Quoted 9 lines · Linus Torvalds

Quoted 7 lines · Dave Jones

NMI watchdog: BUG: soft lockup - CPU#2 stuck for 21s! [trinity-c42:31480]

CPU: 2 PID: 31480 Comm: trinity-c42 Not tainted 3.18.0-rc5+ #91 [loadavg: 174.61 150.35 148.64 9/411 32140]
RIP: 0010:[<ffffffff8a1798b4>]  [<ffffffff8a1798b4>] context_tracking_user_enter+0xa4/0x190
Call Trace:
 [<ffffffff8a012fc5>] syscall_trace_leave+0xa5/0x160
 [<ffffffff8a7d8624>] int_check_syscall_exit_work+0x34/0x3d

Quoted 5 lines

Hmm, if we are getting soft-lockups here, maybe it suggest too much exit-work.

Some TIF_NOHZ loop, perhaps? You have nohz on, don't you?

That makes me wonder: does the problem go away if you disable NOHZ?

Aparently not.

NMI watchdog: BUG: soft lockup - CPU#3 stuck for 22s! [trinity-c75:25175]

CPU: 3 PID: 25175 Comm: trinity-c75 Not tainted 3.18.0-rc5+ #92 [loadavg: 168.72 151.72 150.38 9/410 27945]
task: ffff8800364e44d0 ti: ffff880192d2c000 task.ti: ffff880192d2c000
RIP: 0010:[<ffffffff94175be7>]  [<ffffffff94175be7>] context_tracking_user_exit+0x57/0x120

RSP: 0018:ffff880192d2fee8 EFLAGS: 00000246
RAX: 0000000000000000 RBX: 0000000100000046 RCX: 000000336ee35b47

RDX: 0000000000000001 RSI: ffffffff94ac1e84 RDI: ffffffff94a93725
RBP: ffff880192d2fef8 R08: 00007f9b74d0b740 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: ffffffff940d8503
R13: ffff880192d2fe98 R14: ffffffff943884e7 R15: ffff880192d2fe48
FS:  00007f9b74d0b740(0000) GS:ffff880244600000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 000000336f1b7740 CR3: 0000000229a95000 CR4: 00000000001407e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000600
Stack:
 ffff880192d30000 0000000000080000 ffff880192d2ff78 ffffffff94012c25
 00007f9b747a5000 00007f9b747a5068 0000000000000000 0000000000000000
 0000000000000000 ffffffff9437b3be 0000000000000000 0000000000000000
Call Trace:
 [<ffffffff94012c25>] syscall_trace_enter_phase1+0x125/0x1a0
 [<ffffffff9437b3be>] ? trace_hardirqs_on_thunk+0x3a/0x3f
 [<ffffffff947d41bf>] tracesys+0x14/0x4a
Code: 42 fd ff 48 c7 c7 7a 1e ac 94 e8 25 29 21 00 65 8b 04 25 34 f7 1c 00 83 f8 01 74 28 f6 c7 02 74 13 0f 1f 00 e8 bb 43 fd ff 53 9d <5b> 41 5c 5d c3 0f 1f 40 00 53 9d e8 89 42 fd ff eb ee 0f 1f 80 
sending NMI to other CPUs:
NMI backtrace for cpu 1
CPU: 1 PID: 25164 Comm: trinity-c64 Not tainted 3.18.0-rc5+ #92 [loadavg: 168.72 151.72 150.38 9/410 27945]
task: ffff88011600dbc0 ti: ffff8801a99a4000 task.ti: ffff8801a99a4000
RIP: 0010:[<ffffffff940fb71e>]  [<ffffffff940fb71e>] generic_exec_single+0xee/0x1a0
RSP: 0018:ffff8801a99a7d18  EFLAGS: 00000202
RAX: 0000000000000000 RBX: ffff8801a99a7d20 RCX: 0000000000000038
RDX: 00000000000000ff RSI: 0000000000000008 RDI: 0000000000000000
RBP: ffff8801a99a7d78 R08: ffff880242b57ce0 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000003
R13: 0000000000000001 R14: ffff880083c28948 R15: ffffffff94166aa0
FS:  00007f9b74d0b740(0000) GS:ffff880244200000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 0000000000000001 CR3: 00000001d8611000 CR4: 00000000001407e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000600
Stack:
 ffff8801a99a7d28 0000000000000000 ffffffff94166aa0 ffff880083c28948
 0000000000000003 00000000e38f9aac ffff880083c28948 00000000ffffffff
 0000000000000003 ffffffff94166aa0 ffff880083c28948 0000000000000001
Call Trace:
 [<ffffffff94166aa0>] ? perf_swevent_add+0x120/0x120
 [<ffffffff94166aa0>] ? perf_swevent_add+0x120/0x120
 [<ffffffff940fb89a>] smp_call_function_single+0x6a/0xe0

 [<ffffffff940a172b>] ? preempt_count_sub+0x7b/0x100
 [<ffffffff941671aa>] perf_event_read+0xca/0xd0
 [<ffffffff94167240>] perf_event_read_value+0x90/0xe0
 [<ffffffff941689c6>] perf_read+0x226/0x370
 [<ffffffff942fbfb7>] ? security_file_permission+0x87/0xa0
 [<ffffffff941eafff>] vfs_read+0x9f/0x180
 [<ffffffff941ebbd8>] SyS_read+0x58/0xd0
 [<ffffffff947d42c9>] tracesys_phase2+0xd4/0xd9

Code: 48 89 de 48 03 14 c5 20 65 d1 94 48 89 df e8 8a 4b 28 00 84 c0 75 46 45 85 ed 74 11 f6 43 18 01 74 0b 0f 1f 00 f3 90 f6 43 18 01 <75> f8 31 c0 48 8b 4d c8 65 48 33 0c 25 28 00 00 00 0f 85 8e 00 
NMI backtrace for cpu 0
INFO: NMI handler (arch_trigger_all_cpu_backtrace_handler) took too long to run: 35.055 msecs
CPU: 0 PID: 0 Comm: swapper/0 Not tainted 3.18.0-rc5+ #92 [loadavg: 168.72 151.72 150.38 11/410 27945]
task: ffffffff94c164c0 ti: ffffffff94c00000 task.ti: ffffffff94c00000
RIP: 0010:[<ffffffff943dd415>]  [<ffffffff943dd415>] intel_idle+0xd5/0x180
RSP: 0018:ffffffff94c03e28  EFLAGS: 00000046
RAX: 0000000000000032 RBX: 0000000000000010 RCX: 0000000000000001
RDX: 0000000000000000 RSI: ffffffff94c03fd8 RDI: 0000000000000000
RBP: ffffffff94c03e58 R08: 000000008baf8b86 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000005
R13: 0000000000000032 R14: 0000000000000004 R15: ffffffff94c00000
FS:  0000000000000000(0000) GS:ffff880244000000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007f162e060000 CR3: 0000000014c11000 CR4: 00000000001407f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000600
Stack:
 0000000094c03e58 5955c5b31ad5e8cf ffffe8fffee031a8 0000000000000005
 ffffffff94ca9dc0 0000000000000000 ffffffff94c03ea8 ffffffff94661f05
 00001cb7dcf6fd93 ffffffff94ca9f90 ffffffff94c00000 ffffffff94d18870
Call[31557.908912] NMI backtrace for cpu 2
INFO: NMI handler (arch_trigger_all_cpu_backtrace_handler) took too long to run: 68.178 msecs
CPU: 2 PID: 0 Comm: swapper/2 Not tainted 3.18.0-rc5+ #92 [loadavg: 168.72 151.72 150.38 10/410 27945]
task: ffff880242b596f0 ti: ffff880242b6c000 task.ti: ffff880242b6c000
RIP: 0010:[<ffffffff943dd415>]  [<ffffffff943dd415>] intel_idle+0xd5/0x180
RSP: 0018:ffff880242b6fdf8  EFLAGS: 00000046
RAX: 0000000000000032 RBX: 0000000000000010 RCX: 0000000000000001
RDX: 0000000000000000 RSI: ffff880242b6ffd8 RDI: 0000000000000002
RBP: ffff880242b6fe28 R08: 000000008baf8b86 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000005
R13: 0000000000000032 R14: 0000000000000004 R15: ffff880242b6c000
FS:  0000000000000000(0000) GS:ffff880244400000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 0000000000000000 CR3: 0000000014c11000 CR4: 00000000001407e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000600
Stack:
 0000000242b6fe28 da97aa9b9f42090a ffffe8ffff2031a8 0000000000000005
 ffffffff94ca9dc0 0000000000000002 ffff880242b6fe78 ffffffff94661f05
 00001cb7dcdd1af6 ffffffff94ca9f90 ffff880242b6c000 ffffffff94d18870
Call Trace:
 [<ffffffff94661f05>] cpuidle_enter_state+0x55/0x1c0
 [<ffffffff94662127>] cpuidle_enter+0x17/0x20
 [<ffffffff940b94a3>] cpu_startup_entry+0x423/0x4d0
 [<ffffffff9402b763>] start_secondary+0x1a3/0x220
Code: 31 d2 65 48 8b 34 25 08 ba 00 00 48 8d 86 38 c0 ff ff 48 89 d1 0f 01 c8 48 8b 86 38 c0 ff ff a8 08 75 08 b1 01 4c 89 e8 0f 01 c9 <65> 48 8b 0c 25 08 ba 00 00 f0 80 a1 3a c0 ff ff df 0f ae f0 48 

INFO: NMI handler (arch_trigger_all_cpu_backtrace_handler) took too long to run: 95.994 msecs

<tangent>

Also, today I learned we can reach the perf_event_read code from read(). Given I had /proc/sys/kernel/perf_event_paranoid set to 1, I'm not sure how this is even possible. The only user of perf_fops is perf_event_open syscall _after_ it's checked that sysctl.

Oh, there's an ioctl path to perf too. Though trinity doesn't know anything about it, so I find it surprising if it managed to pull the right combination of entropy to make that do the right thing. Still, that ioctl path probably needs to also be checking that sysctl shouldn't it ?

Dave

TIF_NOHZ is not the same thing as NOHZ. Can you try a kernel with CONFIG_CONTEXT_TRACKING=n? Doing that may involve fiddling with RCU settings a bit. The normal no HZ idle stuff has nothing to do with TIF_NOHZ, and you either have TIF_NOHZ set or you have some kind of thread_info corruption going on here.

Quoted 2 lines

RSP: 0018:ffff880192d2fee8 EFLAGS: 00000246
RAX: 0000000000000000 RBX: 0000000100000046 RCX: 000000336ee35b47

                                    ^^^^^^^^^

That is a strange coincidence. Where did 0x46 | (1<<32) come from? That's a sensible interrupts-disabled flags value with the high part set to 0x1. Those high bits are undefined, but they ought to all be zero.

Quoted 5 lines

 [<ffffffff941689c6>] perf_read+0x226/0x370
 [<ffffffff942fbfb7>] ? security_file_permission+0x87/0xa0
 [<ffffffff941eafff>] vfs_read+0x9f/0x180
 [<ffffffff941ebbd8>] SyS_read+0x58/0xd0
 [<ffffffff947d42c9>] tracesys_phase2+0xd4/0xd9

Riddle me this: what are we doing in tracesys_phase2? This is a full slow-path syscall. TIF_NOHZ doesn't cause that, I think. I'd love to see the value of ti->flags here. Is trinity using ptrace?

I got a report lately involving context tracking. Not sure if it's the same here but the issue was that context tracking uses per cpu data and per cpu allocation use vmalloc and vmalloc'ed area can fault due to lazy paging.

This box is usually pretty solid, but it's been in service as a 24/7 fuzzing box for over a year now, so it's not outside the realm of possibility that this could all be a hardware fault if some memory has gone bad or the like.

TIF_NOHZ is 19 (i.e. _TIF_SYSCALL_TRACE | _TIF_NOTIFY_RESUME | _TIF_SINGLESTEP), not (1<<19).

This code is involved in Dave's trinity lockup, but I don't see why it would cause any of the problems he's seeing, except inadvertently by causing a different path through entry_64.S's syscall handling.

Quoted 3 lines

Is it possible that we've managed to return to userspace with interrupts off somehow? A loop in userspace that somehow has interrupts off can cause all kinds of fun lockups.

That sounds unlikely, but if there is some stack corruption going on.

However, it wouldn't even explain things, because even if interrupts had been disabled in user space, and even if that popf got executed, this wouldn't be where they got enabled. That would be the :"sti" in the system call entry path (hidden behind the ENABLE_INTERRUPTS macro).

Of course, maybe Dave has paravirtualization enabled (what a crock _that_ is), and there is something wrong with that whole code.

Quoted 4 lines · Frederic Weisbecker

I got a report lately involving context tracking. Not sure if it's the same here but the issue was that context tracking uses per cpu data and per cpu allocation use vmalloc and vmalloc'ed area can fault due to lazy paging.

This is complete nonsense. pcpu allocations are populated right away. Otherwise no single line of kernel code which uses dynamically allocated per cpu storage would be safe.

Quoted 4 lines · Dave Jones

This box is usually pretty solid, but it's been in service as a 24/7 fuzzing box for over a year now, so it's not outside the realm of possibility that this could all be a hardware fault if some memory has gone bad or the like.

You could grep old logs for "Hardware Error" and the usual suspects coming from MCE/EDAC. Also /var/log/mcelog or something like that, depending on what's running on that box.

Quoted 9 lines · Thomas Gleixner

Quoted 4 lines · Frederic Weisbecker

I got a report lately involving context tracking. Not sure if it's the same here but the issue was that context tracking uses per cpu data and per cpu allocation use vmalloc and vmalloc'ed area can fault due to lazy paging.

This is complete nonsense. pcpu allocations are populated right away. Otherwise no single line of kernel code which uses dynamically allocated per cpu storage would be safe.

Note this isn't faulting because part of the allocation is swapped. No it's all reserved in the physical memory, but it's a lazy allocation. Part of it isn't yet addressed in the P[UGM?]D. That's what vmalloc_fault() is for.

So it's a non-blocking/sleeping fault which is why it's probably fine most of the time except on code that isn't fault-safe. And I suspect that most people assume that kernel data won't fault so probably some other places have similar issues.

That's a long standing issue. We even had to convert the perf callchain allocation to ad-hoc kmalloc() based per cpu allocation to get over vmalloc faults. At that time, NMIs couldn't handle faults and many callchains were populated in NMIs. We had serious crashes because of per cpu memory faults.

I think that lazy adressing is there for allocation performance reasons. But still having faultable per cpu memory is insame IMHO.

Quoted 73 lines · Frederic Weisbecker

Quoted 71 lines · Linus Torvalds

Quoted 11 lines · Linus Torvalds

So it hasn't actually done the "push %rbx; popfq" part - there must be a label at the return part, and context_tracking_user_exit() never actually did the local_irq_save/restore at all. Which means that it took one of the early exits instead:

        if (!context_tracking_is_enabled())
                return;

        if (in_interrupt())
                return;

Ho humm. Interesting. Neither of those should possibly have happened.

We "know" that "context_tracking_is_enabled()" must be true, because the only way we get to context_tracking_user_exit() in the first place is through "user_exit()", which does:

        if (context_tracking_is_enabled())
                context_tracking_user_exit();

and we know we shouldn't be in_interrupt(), because the backtrace is the system call entry path, for chrissake!

So we definitely have some corruption going on. A few possibilities:

- either the register contents are corrupted (%rbx in your dump said
"0x0000000100000046", but the eflags we restored was 0x246)

- in_interrupt() is wrong, and we've had some irq_count() corruption.
I'd expect that to result in "scheduling while atomic" messages, though, especially if it goes on long enough that you get a watchdog event..

- there is something rotten in the land of
context_tracking_is_enabled(), which uses a static key.

- I have misread the whole trace, and am a moron. But your earlier
report really had some very similar things, just in context_tracking_user_enter() instead of exit.

In your previous oops, the registers that was allegedly used to restore %eflags was %r12:

28: 41 54 push %r12
2a: 9d popfq

  2b:* 5b                   pop    %rbx <-- trapping instruction
  2c: 41 5c                 pop    %r12

2e: 5d pop %rbp
2f: c3 retq

but:

R12: ffff880101ee3ec0
EFLAGS: 00000282

so again, it looks like we never actually did that "popfq" instruction, and it would have exited through the (same) early exits.

But what an odd coincidence that it ended up in both of your reports being *exactly* at that instruction after the "popf". If it had actually *taken* the popf, I'd not be so surprised ("ok, popf enabled interrupts, and there was an interrupt pending"), but since everything seems to say that it came there through some control flow that did *not* go through the popf, that's just a very odd coincidence.

And both context_tracking_user_enter() and exit() have that exact same issue with the early returns. They shouldn't have happened in the first place.

Quoted 4 lines

I got a report lately involving context tracking. Not sure if it's the same here but the issue was that context tracking uses per cpu data and per cpu allocation use vmalloc and vmalloc'ed area can fault due to lazy paging.

Wait, what? If something like kernel_stack ends with an unmapped pmd, we are well and truly screwed.

Quoted 80 lines · Andy Lutomirski

Quoted 77 lines · Frederic Weisbecker

Quoted 68 lines · Linus Torvalds

Quoted 11 lines · Linus Torvalds

So it hasn't actually done the "push %rbx; popfq" part - there must be a label at the return part, and context_tracking_user_exit() never actually did the local_irq_save/restore at all. Which means that it took one of the early exits instead:

        if (!context_tracking_is_enabled())
                return;

        if (in_interrupt())
                return;

Ho humm. Interesting. Neither of those should possibly have happened.

We "know" that "context_tracking_is_enabled()" must be true, because the only way we get to context_tracking_user_exit() in the first place is through "user_exit()", which does:

        if (context_tracking_is_enabled())
                context_tracking_user_exit();

and we know we shouldn't be in_interrupt(), because the backtrace is the system call entry path, for chrissake!

So we definitely have some corruption going on. A few possibilities:

- either the register contents are corrupted (%rbx in your dump said
"0x0000000100000046", but the eflags we restored was 0x246)

- in_interrupt() is wrong, and we've had some irq_count() corruption.
I'd expect that to result in "scheduling while atomic" messages, though, especially if it goes on long enough that you get a watchdog event..

- there is something rotten in the land of
context_tracking_is_enabled(), which uses a static key.

- I have misread the whole trace, and am a moron. But your earlier
report really had some very similar things, just in context_tracking_user_enter() instead of exit.

In your previous oops, the registers that was allegedly used to restore %eflags was %r12:

28: 41 54 push %r12
2a: 9d popfq

  2b:* 5b                   pop    %rbx <-- trapping instruction
  2c: 41 5c                 pop    %r12

2e: 5d pop %rbp
2f: c3 retq

but:

R12: ffff880101ee3ec0
EFLAGS: 00000282

so again, it looks like we never actually did that "popfq" instruction, and it would have exited through the (same) early exits.

But what an odd coincidence that it ended up in both of your reports being *exactly* at that instruction after the "popf". If it had actually *taken* the popf, I'd not be so surprised ("ok, popf enabled interrupts, and there was an interrupt pending"), but since everything seems to say that it came there through some control flow that did *not* go through the popf, that's just a very odd coincidence.

Quoted 3 lines

And both context_tracking_user_enter() and exit() have that exact same issue with the early returns. They shouldn't have happened in the first place.

I got a report lately involving context tracking. Not sure if it's the same here but the issue was that context tracking uses per cpu data and per cpu allocation use vmalloc and vmalloc'ed area can fault due to lazy paging.

Quoted 2 lines

Wait, what? If something like kernel_stack ends with an unmapped pmd, we are well and truly screwed.

Note that's non-sleeping faults. So probably most places are fine except a few of them that really don't want exception to mess up some state. I can imagine some entry code that really don't want that.

Is kernel stack allocated by vmalloc or alloc_percpu()?

Quoted 20 lines · Frederic Weisbecker

Quoted 9 lines · Thomas Gleixner

Quoted 4 lines · Frederic Weisbecker

I got a report lately involving context tracking. Not sure if it's the same here but the issue was that context tracking uses per cpu data and per cpu allocation use vmalloc and vmalloc'ed area can fault due to lazy paging.

This is complete nonsense. pcpu allocations are populated right away. Otherwise no single line of kernel code which uses dynamically allocated per cpu storage would be safe.

Note this isn't faulting because part of the allocation is swapped. No it's all reserved in the physical memory, but it's a lazy allocation. Part of it isn't yet addressed in the P[UGM?]D. That's what vmalloc_fault() is for.

So it's a non-blocking/sleeping fault which is why it's probably fine most of the time except on code that isn't fault-safe. And I suspect that most people assume that kernel data won't fault so probably some other places have similar issues.

Quoted 4 lines

That's a long standing issue. We even had to convert the perf callchain allocation to ad-hoc kmalloc() based per cpu allocation to get over vmalloc faults. At that time, NMIs couldn't handle faults and many callchains were populated in NMIs. We had serious crashes because of per cpu memory faults.

Is there seriously more than 512GB of per-cpu virtual space or whatever's needed to exceed a single pgd on x86_64?

And there are definitely placed that access per-cpu data in contexts in which a non-IST fault is not allowed. Maybe not dynamic per-cpu data, though.

Quoted 6 lines · Thomas Gleixner

Quoted 4 lines · Frederic Weisbecker

I got a report lately involving context tracking. Not sure if it's the same here but the issue was that context tracking uses per cpu data and per cpu allocation use vmalloc and vmalloc'ed area can fault due to lazy paging.

Quoted 3 lines

This is complete nonsense. pcpu allocations are populated right away. Otherwise no single line of kernel code which uses dynamically allocated per cpu storage would be safe.

Note this isn't faulting because part of the allocation is swapped. No it's all reserved in the physical memory, but it's a lazy allocation. Part of it isn't yet addressed in the P[UGM?]D. That's what vmalloc_fault() is for.

Quoted 3 lines · Frederic Weisbecker

Note that's non-sleeping faults. So probably most places are fine except a few of them that really don't want exception to mess up some state. I can imagine some entry code that really don't want that.

Any non-IST fault at all on the kernel_stack reference in system_call is instant root on non-SMAP systems and instant double-fault or more challenging root on SMAP systems. The issue is that rsp is user-controlled, so the CPU cannot deliver a non-IST fault safely.

Quoted 2 lines

Is kernel stack allocated by vmalloc or alloc_percpu()?

DEFINE_PER_CPU(unsigned long, kernel_stack)

Note that I'm talking about kernel_stack, not the kernel stack itself.

The actual stack is regular linearly-mapped memory, although I plan on trying to change that, complete with all kinds of care to avoid double faults.

Quoted 7 lines · Frederic Weisbecker

Quoted 6 lines · Thomas Gleixner

Quoted 4 lines · Frederic Weisbecker

I got a report lately involving context tracking. Not sure if it's the same here but the issue was that context tracking uses per cpu data and per cpu allocation use vmalloc and vmalloc'ed area can fault due to lazy paging.

Quoted 8 lines

Quoted 3 lines

This is complete nonsense. pcpu allocations are populated right away. Otherwise no single line of kernel code which uses dynamically allocated per cpu storage would be safe.

Note this isn't faulting because part of the allocation is swapped. No it's all reserved in the physical memory, but it's a lazy allocation. Part of it isn't yet addressed in the P[UGM?]D. That's what vmalloc_fault() is for.

Sorry, I can't follow your argumentation here.

pcpu_alloc()
....
area_found:

   ....

        /* clear the areas and return address relative to base address */
        for_each_possible_cpu(cpu)
                memset((void *)pcpu_chunk_addr(chunk, cpu, 0) + off, 0, size);

How would that memset fail to establish the mapping, which is btw. already established via:

pcpu_populate_chunk()

already before that memset?

Are we talking about different per cpu allocators here or am I missing something completely non obvious?

Thanks,

tglx

Quoted 7 lines · Frederic Weisbecker

Quoted 6 lines · Thomas Gleixner

Quoted 4 lines · Frederic Weisbecker

I got a report lately involving context tracking. Not sure if it's the same here but the issue was that context tracking uses per cpu data and per cpu allocation use vmalloc and vmalloc'ed area can fault due to lazy paging.

Quoted 8 lines

Quoted 3 lines

This is complete nonsense. pcpu allocations are populated right away. Otherwise no single line of kernel code which uses dynamically allocated per cpu storage would be safe.

Note this isn't faulting because part of the allocation is swapped. No it's all reserved in the physical memory, but it's a lazy allocation. Part of it isn't yet addressed in the P[UGM?]D. That's what vmalloc_fault() is for.

Sorry, I can't follow your argumentation here.

pcpu_alloc()
....
area_found:

   ....

        /* clear the areas and return address relative to base address */
        for_each_possible_cpu(cpu)
                memset((void *)pcpu_chunk_addr(chunk, cpu, 0) + off, 0, size);

How would that memset fail to establish the mapping, which is btw. already established via:

pcpu_populate_chunk()

already before that memset?

Quoted 14 lines · Thomas Gleixner

Sorry, I can't follow your argumentation here.

pcpu_alloc()
....
area_found:

   ....

        /* clear the areas and return address relative to base address */
        for_each_possible_cpu(cpu)
                memset((void *)pcpu_chunk_addr(chunk, cpu, 0) + off, 0, size);

How would that memset fail to establish the mapping, which is btw. already established via:

Quoted 3 lines

pcpu_populate_chunk()

already before that memset?

I think that this will map them into init_mm->pgd and current->active_mm->pgd, but it won't necessarily map them into the rest of the pgds.

Quoted 17 lines · Andy Lutomirski

Quoted 16 lines · Thomas Gleixner

Sorry, I can't follow your argumentation here.

pcpu_alloc()
....
area_found:

   ....

        /* clear the areas and return address relative to base address */
        for_each_possible_cpu(cpu)
                memset((void *)pcpu_chunk_addr(chunk, cpu, 0) + off, 0, size);

How would that memset fail to establish the mapping, which is btw. already established via:

pcpu_populate_chunk()

Quoted 5 lines

Quoted 1 line

already before that memset?

I think that this will map them into init_mm->pgd and current->active_mm->pgd, but it won't necessarily map them into the rest of the pgds.

And why would mapping them into the kernel mapping, i.e. init_mm not be sufficient?

We are talking about kernel memory and not some random user space mapping.

Thanks,

tglx

This is why I think that the grsec kernels will crash on very large memory systems. They don't seem to get this right for the kernel stack, and a page fault trying to access the stack is a big no-no.

Quoted 4 lines · Andy Lutomirski

This is why I think that the grsec kernels will crash on very large memory systems. They don't seem to get this right for the kernel stack, and a page fault trying to access the stack is a big no-no.

For something like a stack, that's trivial, you could just probe it before the actual task switch.

So I wouldn't worry about the kernel stack itself (although I think vmallocing it isn't likely worth it),

I'd worry more about some other
random dynamic percpu allocation. Although they arguably shouldn't happen for low-level code that cannot handle the dynamic pgd-population. And they generally don't.

It's really tracing that tends to be a special case not because of any particular low-level code issue, but because instrumenting itself recursively tends to be a bad idea.

Linus

I thought so for a while, too, but now I disagree. On PGE hardware, it seems entirely possible that the new stack would be in the TLB even if it's not visible via cr3. Then, as soon as the TLB entry expires, we double-fault.

I don't want vmalloc to avoid low-order allocations -- I want it to have guard pages. The fact that a user-triggerable stack overflow is basically root right now and doesn't reliably OOPS scares me.

Quoted 5 lines · Andy Lutomirski

I thought so for a while, too, but now I disagree. On PGE hardware, it seems entirely possible that the new stack would be in the TLB even if it's not visible via cr3. Then, as soon as the TLB entry expires, we double-fault.

Ahh. Good point.

Quoted 3 lines

I don't want vmalloc to avoid low-order allocations -- I want it to have guard pages. The fact that a user-triggerable stack overflow is basically root right now and doesn't reliably OOPS scares me.

Well, if you do that, you would have to make the double-fault handler aware of the stack issue anyway, and then you could just do teh same PGD repopulation that a page fault does and return (for the case where you didn't overflow the stack, just had the page tables unpopulated - obviously an actual stack overflow should do something more drastic).

And you were calling me crazy? :)

We could be restarting just about anything if that happens. Except that if we double-faulted on a trap gate entry instead of an interrupt gate entry, then we can't restart, and, unless we can somehow decode the error code usefully (it's woefully undocumented), int 0x80 and int3 might be impossible to handle correctly if it double-faults. And please don't suggest moving int 0x80 to an IST stack :)

Quoted 2 lines · Andy Lutomirski

And you were calling me crazy? :)

Hey, I'm crazy like a fox.

Quoted 6 lines

We could be restarting just about anything if that happens. Except that if we double-faulted on a trap gate entry instead of an interrupt gate entry, then we can't restart, and, unless we can somehow decode the error code usefully (it's woefully undocumented), int 0x80 and int3 might be impossible to handle correctly if it double-faults. And please don't suggest moving int 0x80 to an IST stack :)

No, no. So tell me if this won't work:

- when forking a new process, make sure we allocate the vmalloc stack
*before* we copy the vm

- this should guarantee that all new processes will at least have its
*own* stack always in its page tables, since vmalloc always fills in the page table of the current page tables of the thread doing the vmalloc.

HOWEVER, that leaves the task switch *to* that process, and making sure that the stack pointer is ok in between the "switch %rsp" and "switch %cr3".

So then we make the rule be: switch %cr3 *before* switching %rsp, and only in between those places can we get in trouble. Yes/no?

And that small section is all with interrupts disabled, and nothing should take an exception. The C code might take a double fault on a regular access to the old stack (the *new* stack is guaranteed to be mapped, but the old stack is not), but that should be very similar to what we already do with "iret". So we can just fill in the page tables and return.

For safety, add a percpu counter that is cleared before the %cr3 setting, to make sure that we only do a *single* double-fault, but it really sounds pretty safe. No?

The only deadly thing would be NMI, but that's an IST anyway, so not an issue. No other traps should be able to happen except the double page table miss.

But hey, maybe I'm not crazy like a fox. Maybe I'm just plain crazy, and I missed something else.

And no, I don't think the above is necessarily a *good* idea. But it doesn't seem really overly complicated either.

Linus

Quoted 20 lines · Dave Jones

Quoted 4 lines · Don Zickus

Quoted 2 lines

So here we mangle CPU3 in and lose the backtrace for cpu0, which might be the real interesting one ....

Can you provide another dump? The hope is we get something not mangled?

Working on it..

Quoted 4 lines

The other option we have done in RHEL is panic the system and let kdump capture the memory. Then we can analyze the vmcore for the stack trace cpu0 stored in memory to get a rough idea where it might be if the cpu isn't responding very well.

I don't know if it's because of the debug options I typically run with, or that I'm perpetually cursed, but I've never managed to get kdump to do anything useful. (The last time I tried it was actively harmful in that not only did it fail to dump anything, it wedged the machine so it didn't reboot after panic).

Quoted 3 lines

Unless there's some magic step missing from the documentation at
http://fedoraproject.org/wiki/How_to_use_kdump_to_debug_kernel_crashes
then I'm not optimistic it'll be useful.

Well, I don't know when the last time you ran it, but I know the RH kexec folks have started pursuing a Fedora-first package patch rule a couple of years ago to ensure Fedora had a working kexec/kdump solution.

As for the wedging part, it was a common problem to have the kernel hang while trying to boot the second kernel (and before console output happened). So the problem makes sense and is unfortunate. I would encourage you to try again. :-)

Nothing, but it wouldn't be the first time I'd seen a hardware fault that didn't raise an MCE.

Quoted 2 lines

Are we talking about different per cpu allocators here or am I missing something completely non obvious?

That's the same allocator yeah. So if the whole memory is dereferenced, faults shouldn't happen indeed.

Maybe that was a bug a few years ago but not anymore.

Is it possible that, somehow, some part isn't zeroed by pcpu_alloc()? After all it's allocated with vzalloc() so that part could be skipped. The memset(0)

Quoted 4 lines · Linus Torvalds

Hmm, if we are getting soft-lockups here, maybe it suggest too much exit-work.

Some TIF_NOHZ loop, perhaps? You have nohz on, don't you?

Quoted 1 line

That makes me wonder: does the problem go away if you disable NOHZ?

Does nohz=off do enough ? I couldn't convince myself after looking at dmesg, and still seeing dynticks stuff in there.

I'll do a rebuild with all the CONFIG_NO_HZ stuff off, though it also changes some other config stuff wrt timers.

Quoted 9 lines · Linus Torvalds

Quoted 7 lines · Dave Jones

NMI watchdog: BUG: soft lockup - CPU#2 stuck for 21s! [trinity-c42:31480]

CPU: 2 PID: 31480 Comm: trinity-c42 Not tainted 3.18.0-rc5+ #91 [loadavg: 174.61 150.35 148.64 9/411 32140]
RIP: 0010:[<ffffffff8a1798b4>]  [<ffffffff8a1798b4>] context_tracking_user_enter+0xa4/0x190
Call Trace:
 [<ffffffff8a012fc5>] syscall_trace_leave+0xa5/0x160
 [<ffffffff8a7d8624>] int_check_syscall_exit_work+0x34/0x3d

Quoted 5 lines

Hmm, if we are getting soft-lockups here, maybe it suggest too much exit-work.

Some TIF_NOHZ loop, perhaps? You have nohz on, don't you?

That makes me wonder: does the problem go away if you disable NOHZ?

Aparently not.

NMI watchdog: BUG: soft lockup - CPU#3 stuck for 22s! [trinity-c75:25175]

CPU: 3 PID: 25175 Comm: trinity-c75 Not tainted 3.18.0-rc5+ #92 [loadavg: 168.72 151.72 150.38 9/410 27945]
task: ffff8800364e44d0 ti: ffff880192d2c000 task.ti: ffff880192d2c000
RIP: 0010:[<ffffffff94175be7>]  [<ffffffff94175be7>] context_tracking_user_exit+0x57/0x120
RSP: 0018:ffff880192d2fee8  EFLAGS: 00000246
RAX: 0000000000000000 RBX: 0000000100000046 RCX: 000000336ee35b47
RDX: 0000000000000001 RSI: ffffffff94ac1e84 RDI: ffffffff94a93725
RBP: ffff880192d2fef8 R08: 00007f9b74d0b740 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: ffffffff940d8503
R13: ffff880192d2fe98 R14: ffffffff943884e7 R15: ffff880192d2fe48
FS:  00007f9b74d0b740(0000) GS:ffff880244600000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 000000336f1b7740 CR3: 0000000229a95000 CR4: 00000000001407e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000600
Stack:
 ffff880192d30000 0000000000080000 ffff880192d2ff78 ffffffff94012c25
 00007f9b747a5000 00007f9b747a5068 0000000000000000 0000000000000000
 0000000000000000 ffffffff9437b3be 0000000000000000 0000000000000000
Call Trace:
 [<ffffffff94012c25>] syscall_trace_enter_phase1+0x125/0x1a0
 [<ffffffff9437b3be>] ? trace_hardirqs_on_thunk+0x3a/0x3f
 [<ffffffff947d41bf>] tracesys+0x14/0x4a
Code: 42 fd ff 48 c7 c7 7a 1e ac 94 e8 25 29 21 00 65 8b 04 25 34 f7 1c 00 83 f8 01 74 28 f6 c7 02 74 13 0f 1f 00 e8 bb 43 fd ff 53 9d <5b> 41 5c 5d c3 0f 1f 40 00 53 9d e8 89 42 fd ff eb ee 0f 1f 80 
sending NMI to other CPUs:
NMI backtrace for cpu 1
CPU: 1 PID: 25164 Comm: trinity-c64 Not tainted 3.18.0-rc5+ #92 [loadavg: 168.72 151.72 150.38 9/410 27945]
task: ffff88011600dbc0 ti: ffff8801a99a4000 task.ti: ffff8801a99a4000
RIP: 0010:[<ffffffff940fb71e>]  [<ffffffff940fb71e>] generic_exec_single+0xee/0x1a0
RSP: 0018:ffff8801a99a7d18  EFLAGS: 00000202
RAX: 0000000000000000 RBX: ffff8801a99a7d20 RCX: 0000000000000038
RDX: 00000000000000ff RSI: 0000000000000008 RDI: 0000000000000000
RBP: ffff8801a99a7d78 R08: ffff880242b57ce0 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000003
R13: 0000000000000001 R14: ffff880083c28948 R15: ffffffff94166aa0
FS:  00007f9b74d0b740(0000) GS:ffff880244200000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 0000000000000001 CR3: 00000001d8611000 CR4: 00000000001407e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000600

Stack:
 ffff8801a99a7d28 0000000000000000 ffffffff94166aa0 ffff880083c28948
 0000000000000003 00000000e38f9aac ffff880083c28948 00000000ffffffff
 0000000000000003 ffffffff94166aa0 ffff880083c28948 0000000000000001
Call Trace:
 [<ffffffff94166aa0>] ? perf_swevent_add+0x120/0x120
 [<ffffffff94166aa0>] ? perf_swevent_add+0x120/0x120
 [<ffffffff940fb89a>] smp_call_function_single+0x6a/0xe0

[<ffffffff940a172b>] ? preempt_count_sub+0x7b/0x100

 [<ffffffff941671aa>] perf_event_read+0xca/0xd0
 [<ffffffff94167240>] perf_event_read_value+0x90/0xe0
 [<ffffffff941689c6>] perf_read+0x226/0x370
 [<ffffffff942fbfb7>] ? security_file_permission+0x87/0xa0
 [<ffffffff941eafff>] vfs_read+0x9f/0x180
 [<ffffffff941ebbd8>] SyS_read+0x58/0xd0
 [<ffffffff947d42c9>] tracesys_phase2+0xd4/0xd9

Quoted 7 lines · Linus Torvalds

Quoted 3 lines

Quoted 1 line

I'll try that next, and check in on it tomorrow.

No luck. Died even faster this time.

Yeah, and your other lockups haven't even been TLB related. Not that they look like anything else *either*.

Quoted 8 lines

I have no ideas left. I'd go for a bisection - rather than try random things, at least bisection will get us a smaller set of suspects if you can go through a few cycles of it. Even if you decide that you want to run for most of a day before you are convinced it's all good, a couple of days should get you a handful of bisection points (that's assuming you hit a couple of bad ones too that turn bad in a shorter while). And 4 or five bisections should get us from 11k commits down to the ~600 commit range. That would be a huge improvement.

Great start to the week: I decided to confirm my recollection that .17 was ok, only to hit this within 10 minutes.

Kernel panic - not syncing: Watchdog detected hard LOCKUP on cpu 3
CPU: 3 PID: 17176 Comm: trinity-c95 Not tainted 3.17.0+ #87
 0000000000000000 00000000f3a61725 ffff880244606bf0 ffffffff9583e9fa
 ffffffff95c67918 ffff880244606c78 ffffffff9583bcc0 0000000000000010
 ffff880244606c88 ffff880244606c20 00000000f3a61725 0000000000000000
Call Trace:
 <NMI>  [<ffffffff9583e9fa>] dump_stack+0x4e/0x7a
 [<ffffffff9583bcc0>] panic+0xd4/0x207
 [<ffffffff95150908>] watchdog_overflow_callback+0x118/0x120
 [<ffffffff95193dbe>] __perf_event_overflow+0xae/0x340
 [<ffffffff95192230>] ? perf_event_task_disable+0xa0/0xa0
 [<ffffffff9501a7bf>] ? x86_perf_event_set_period+0xbf/0x150
 [<ffffffff95194be4>] perf_event_overflow+0x14/0x20
 [<ffffffff95020676>] intel_pmu_handle_irq+0x206/0x410
 [<ffffffff9501966b>] perf_event_nmi_handler+0x2b/0x50
 [<ffffffff95007bb2>] nmi_handle+0xd2/0x390
 [<ffffffff95007ae5>] ? nmi_handle+0x5/0x390
 [<ffffffff958489b0>] ? _raw_spin_lock_irqsave+0x80/0x90

 [<ffffffff950080a2>] default_do_nmi+0x72/0x1c0
 [<ffffffff950082a8>] do_nmi+0xb8/0x100
 [<ffffffff9584b9aa>] end_repeat_nmi+0x1e/0x2e
 [<ffffffff958489b0>] ? _raw_spin_lock_irqsave+0x80/0x90
 [<ffffffff958489b0>] ? _raw_spin_lock_irqsave+0x80/0x90
 [<ffffffff958489b0>] ? _raw_spin_lock_irqsave+0x80/0x90
 <<EOE>>  <IRQ>  [<ffffffff95101685>] lock_hrtimer_base.isra.18+0x25/0x50
 [<ffffffff951019d3>] hrtimer_try_to_cancel+0x33/0x1f0

 [<ffffffff95101baa>] hrtimer_cancel+0x1a/0x30
 [<ffffffff95113557>] tick_nohz_restart+0x17/0x90
 [<ffffffff95114533>] __tick_nohz_full_check+0xc3/0x100
 [<ffffffff9511457e>] nohz_full_kick_work_func+0xe/0x10
 [<ffffffff95188894>] irq_work_run_list+0x44/0x70
 [<ffffffff951888ea>] irq_work_run+0x2a/0x50
 [<ffffffff9510109b>] update_process_times+0x5b/0x70
 [<ffffffff95113325>] tick_sched_handle.isra.20+0x25/0x60
 [<ffffffff95113801>] tick_sched_timer+0x41/0x60
 [<ffffffff95102281>] __run_hrtimer+0x81/0x480
 [<ffffffff951137c0>] ? tick_sched_do_timer+0xb0/0xb0
 [<ffffffff95102977>] hrtimer_interrupt+0x117/0x270
 [<ffffffff950346d7>] local_apic_timer_interrupt+0x37/0x60
 [<ffffffff9584c44f>] smp_apic_timer_interrupt+0x3f/0x50
 [<ffffffff9584a86f>] apic_timer_interrupt+0x6f/0x80
 <EOI>  [<ffffffff950d3f3a>] ? lock_release_holdtime.part.28+0x9a/0x160
 [<ffffffff950ef3b7>] ? rcu_is_watching+0x27/0x60
 [<ffffffff9508cb75>] kill_pid_info+0xf5/0x130
 [<ffffffff9508ca85>] ? kill_pid_info+0x5/0x130
 [<ffffffff9508ccd3>] SYSC_kill+0x103/0x330
 [<ffffffff9508cc7c>] ? SYSC_kill+0xac/0x330
 [<ffffffff9519b592>] ? context_tracking_user_exit+0x52/0x1a0
 [<ffffffff950d6f1d>] ? trace_hardirqs_on_caller+0x16d/0x210
 [<ffffffff950d6fcd>] ? trace_hardirqs_on+0xd/0x10
 [<ffffffff950137ad>] ? syscall_trace_enter+0x14d/0x330
 [<ffffffff9508f44e>] SyS_kill+0xe/0x10
 [<ffffffff95849b24>] tracesys+0xdd/0xe2

Kernel Offset: 0x14000000 from 0xffffffff81000000 (relocation range: 0xffffffff80000000-0xffffffffbfffffff)

It could a completely different cause for lockup, but seeing this now has me wondering if perhaps it's something unrelated to the kernel. I have recollection of running late .17rc's for days without incident, and I'm pretty sure .17 was ok too. But a few weeks ago I did upgrade that test box to the Fedora 21 beta. Which means I have a new gcc. I'm not sure I really trust 4.9.1 yet, so maybe I'll see if I can get 4.8 back on there and see if that's any better.

Dave

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/

TIF_NOHZ is not the same thing as NOHZ. Can you try a kernel with CONFIG_CONTEXT_TRACKING=n? Doing that may involve fiddling with RCU settings a bit. The normal no HZ idle stuff has nothing to do with TIF_NOHZ, and you either have TIF_NOHZ set or you have some kind of thread_info corruption going on here.

Quoted 35 lines · Dave Jones

Quoted 4 lines · Linus Torvalds

But since you say "several times a day", just for fun, can you test the follow-up patch to that one-liner fix that Will Deacon posted today (Subject: "[PATCH] mmu_gather: move minimal range calculations into generic code"). That does some further cleanup in this area.

A few hours ago it hit the NMI watchdog again with that patch applied. Incomplete trace, but it looks different based on what did make it over. Different RIP at least.

[65155.054155] NMI watchdog: BUG: soft lockup - CPU#1 stuck for 22s! [trinity-c127:12559]
[65155.054573] irq event stamp: 296752
[65155.054589] hardirqs last  enabled at (296751): [<ffffffff9d87403d>] _raw_spin_unlock_irqrestore+0x5d/0x80
[65155.054625] hardirqs last disabled at (296752): [<ffffffff9d875cea>] apic_timer_interrupt+0x6a/0x80
[65155.054657] softirqs last  enabled at (296188): [<ffffffff9d259943>] bdi_queue_work+0x83/0x270
[65155.054688] softirqs last disabled at (296184): [<ffffffff9d259920>] bdi_queue_work+0x60/0x270
[65155.054721] CPU: 1 PID: 12559 Comm: trinity-c127 Not tainted 3.18.0-rc4+ #84 [loadavg: 209.68 187.90 185.33 34/431 17515]
[65155.054795] task: ffff88023f664680 ti: ffff8801649f0000 task.ti: ffff8801649f0000
[65155.054820] RIP: 0010:[<ffffffff9d87403f>]  [<ffffffff9d87403f>] _raw_spin_unlock_irqrestore+0x5f/0x80
[65155.054852] RSP: 0018:ffff8801649f3be8  EFLAGS: 00000292
[65155.054872] RAX: ffff88023f664680 RBX: 0000000000000007 RCX: 0000000000000007
[65155.054895] RDX: 00000000000029e0 RSI: ffff88023f664ea0 RDI: ffff88023f664680
[65155.054919] RBP: ffff8801649f3bf8 R08: 0000000000000000 R09: 0000000000000000
[65155.055956] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
[65155.056985] R13: ffff8801649f3b58 R14: ffffffff9d3e7d0e R15: 00000000000003e0
[65155.058037] FS:  00007f0dc957c700(0000) GS:ffff880244200000(0000) knlGS:0000000000000000
[65155.059083] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[65155.060121] CR2: 00007f0dc958e000 CR3: 000000022f31e000 CR4: 00000000001407e0
[65155.061152] DR0: 00007f54162bc000 DR1: 00007feb92c3d000 DR2: 0000000000000000
[65155.062180] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000600
[65155.063202] Stack:

And that's all she wrote.

Quoted 7 lines

Quoted 5 lines

If Will's patch doesn't make a difference, what about reverting that ce9ec37bddb6? Although it really *is* a "obvious bugfix", and I really don't see why any of this would be noticeable on x86 (it triggered issues on ARM64, but that was because ARM64 cared much more about the exact range).

I'll try that next, and check in on it tomorrow.

No luck. Died even faster this time.

[  772.459481] NMI watchdog: BUG: soft lockup - CPU#3 stuck for 22s! [modprobe:31400]
[  772.459858] irq event stamp: 3362
[  772.459872] hardirqs last  enabled at (3361): [<ffffffff941a437c>] context_tracking_user_enter+0x9c/0x2c0
[  772.459907] hardirqs last disabled at (3362): [<ffffffff94875bea>] apic_timer_interrupt+0x6a/0x80
[  772.459937] softirqs last  enabled at (0): [<ffffffff940764d5>] copy_process.part.26+0x635/0x1d80
[  772.459968] softirqs last disabled at (0): [<          (null)>]           (null)
[  772.459996] CPU: 3 PID: 31400 Comm: modprobe Not tainted 3.18.0-rc4+ #85 [loadavg: 207.70 163.33 92.64 11/433 31547]
[  772.460086] task: ffff88022f0b2f00 ti: ffff88019a944000 task.ti: ffff88019a944000
[  772.460110] RIP: 0010:[<ffffffff941a437e>]  [<ffffffff941a437e>] context_tracking_user_enter+0x9e/0x2c0
[  772.460142] RSP: 0018:ffff88019a947f00  EFLAGS: 00000282
[  772.460161] RAX: ffff88022f0b2f00 RBX: 0000000000000000 RCX: 0000000000000000
[  772.460184] RDX: 0000000000000001 RSI: 0000000000000001 RDI: ffff88022f0b2f00
[  772.460207] RBP: ffff88019a947f10 R08: 0000000000000000 R09: 0000000000000000
[  772.460229] R10: 0000000000000000 R11: 0000000000000000 R12: ffff88019a947e90
[  772.460252] R13: ffffffff940f6d04 R14: ffff88019a947ec0 R15: ffff8802447cd640
[  772.460294] FS:  00007f3b71ee4700(0000) GS:ffff880244600000(0000) knlGS:0000000000000000
[  772.460362] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  772.460391] CR2: 00007fffdad5af58 CR3: 000000011608e000 CR4: 00000000001407e0
[  772.460424] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[  772.460447] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[  772.460470] Stack:
[  772.460480]  ffff88019a947f58 00000000006233a8 ffff88019a947f40 ffffffff9401429d
[  772.460512]  00000000006233a8 000000000041d68a 00000000006233a8 0000000000000000
[  772.460543]  00000000006233a0 ffffffff94874fa4 000000001008feff 000507d93d73a434
[  772.460574] Call Trace:
[  772.461576]  [<ffffffff9401429d>] syscall_trace_leave+0xad/0x2e0
[  772.462572]  [<ffffffff94874fa4>] int_check_syscall_exit_work+0x34/0x3d
[  772.463575] Code: f8 1c 00 84 c0 75 46 48 c7 c7 51 53 cd 94 e8 aa 23 24 00 65 c7 04 25 f4 f8 1c 00 01 00 00 00 f6 c7 02 74 19 e8 84 43 f3 ff 53 9d <5b> 41 5c 5d c3 0f 1f 44 00 00 c3 0f 1f 80 00 00 00 00 53 9d e8 
[  772.465797] Kernel panic - not syncing: softlockup: hung tasks
[  772.466821] CPU: 3 PID: 31400 Comm: modprobe Tainted: G             L 3.18.0-rc4+ #85 [loadavg: 207.70 163.33 92.64 11/433 31547]
[  772.468915]  ffff88022f0b2f00 00000000de65d5f5 ffff880244603dc8 ffffffff94869e01
[  772.470031]  0000000000000000 ffffffff94c7599b ffff880244603e48 ffffffff94866b21
[  772.471085]  ffff880200000008 ffff880244603e58 ffff880244603df8 00000000de65d5f5
[  772.472141] Call Trace:
[  772.473183]  <IRQ>  [<ffffffff94869e01>] dump_stack+0x4f/0x7c
[  772.474253]  [<ffffffff94866b21>] panic+0xcf/0x202
[  772.475346]  [<ffffffff94154d1e>] watchdog_timer_fn+0x27e/0x290
[  772.476414]  [<ffffffff94106297>] __run_hrtimer+0xe7/0x740

[  772.477475]  [<ffffffff94106b64>] ? hrtimer_interrupt+0x94/0x270
[  772.478555]  [<ffffffff94154aa0>] ? watchdog+0x40/0x40
[  772.479627]  [<ffffffff94106be7>] hrtimer_interrupt+0x117/0x270
[  772.480703]  [<ffffffff940303db>] local_apic_timer_interrupt+0x3b/0x70
[  772.481777]  [<ffffffff948777f3>] smp_apic_timer_interrupt+0x43/0x60
[  772.482856]  [<ffffffff94875bef>] apic_timer_interrupt+0x6f/0x80
[  772.483915]  <EOI>  [<ffffffff941a437e>] ? context_tracking_user_enter+0x9e/0x2c0
[  772.484972]  [<ffffffff9401429d>] syscall_trace_leave+0xad/0x2e0

[  772.486042]  [<ffffffff94874fa4>] int_check_syscall_exit_work+0x34/0x3d
[  772.487187] Kernel Offset: 0x13000000 from 0xffffffff81000000 (relocation range: 0xffffffff80000000-0xffffffffbfffffff)

Dave

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/

I am wondering may be in some cases we panic in second kernel and sit there. Probably we should append a kernel command line automatically say "panic=1" so that it reboots itself if second kernel panics.

By any chance, have you enabled "CONFIG_RANDOMIZE_BASE"? If yes, please disable that as currently kexec/kdump stuff does not work with it. And it hangs very early in the boot process and I had to hook serial console to get following message on console.

Quoted 7 lines

dracut: *** Stripping files done ***
dracut: *** Store current command line parameters ***
dracut: *** Creating image file ***
dracut: *** Creating image file done ***
kdumpctl: cat: write error: Broken pipe
kdumpctl: kexec: failed to load kdump kernel
kdumpctl: Starting kdump: [FAILED]

Quoted 21 lines

Great start to the week: I decided to confirm my recollection that .17 was ok, only to hit this within 10 minutes.

Kernel panic - not syncing: Watchdog detected hard LOCKUP on cpu 3
CPU: 3 PID: 17176 Comm: trinity-c95 Not tainted 3.17.0+ #87
 0000000000000000 00000000f3a61725 ffff880244606bf0 ffffffff9583e9fa
 ffffffff95c67918 ffff880244606c78 ffffffff9583bcc0 0000000000000010
 ffff880244606c88 ffff880244606c20 00000000f3a61725 0000000000000000
Call Trace:
 <NMI>  [<ffffffff9583e9fa>] dump_stack+0x4e/0x7a
 [<ffffffff9583bcc0>] panic+0xd4/0x207
 [<ffffffff95150908>] watchdog_overflow_callback+0x118/0x120
 [<ffffffff95193dbe>] __perf_event_overflow+0xae/0x340
 [<ffffffff95192230>] ? perf_event_task_disable+0xa0/0xa0
 [<ffffffff9501a7bf>] ? x86_perf_event_set_period+0xbf/0x150
 [<ffffffff95194be4>] perf_event_overflow+0x14/0x20
 [<ffffffff95020676>] intel_pmu_handle_irq+0x206/0x410
 [<ffffffff9501966b>] perf_event_nmi_handler+0x2b/0x50
 [<ffffffff95007bb2>] nmi_handle+0xd2/0x390
 [<ffffffff95007ae5>] ? nmi_handle+0x5/0x390
 [<ffffffff958489b0>] ? _raw_spin_lock_irqsave+0x80/0x90

Quoted 8 lines

 [<ffffffff950080a2>] default_do_nmi+0x72/0x1c0
 [<ffffffff950082a8>] do_nmi+0xb8/0x100
 [<ffffffff9584b9aa>] end_repeat_nmi+0x1e/0x2e
 [<ffffffff958489b0>] ? _raw_spin_lock_irqsave+0x80/0x90
 [<ffffffff958489b0>] ? _raw_spin_lock_irqsave+0x80/0x90
 [<ffffffff958489b0>] ? _raw_spin_lock_irqsave+0x80/0x90
 <<EOE>>  <IRQ>  [<ffffffff95101685>] lock_hrtimer_base.isra.18+0x25/0x50
 [<ffffffff951019d3>] hrtimer_try_to_cancel+0x33/0x1f0

Ah that one got fixed in the merge window and in -stable, right?

Quoted 30 lines · Frederic Weisbecker

Quoted 29 lines

Great start to the week: I decided to confirm my recollection that .17 was ok, only to hit this within 10 minutes.

Kernel panic - not syncing: Watchdog detected hard LOCKUP on cpu 3
CPU: 3 PID: 17176 Comm: trinity-c95 Not tainted 3.17.0+ #87
 0000000000000000 00000000f3a61725 ffff880244606bf0 ffffffff9583e9fa
 ffffffff95c67918 ffff880244606c78 ffffffff9583bcc0 0000000000000010
 ffff880244606c88 ffff880244606c20 00000000f3a61725 0000000000000000
Call Trace:
 <NMI>  [<ffffffff9583e9fa>] dump_stack+0x4e/0x7a
 [<ffffffff9583bcc0>] panic+0xd4/0x207
 [<ffffffff95150908>] watchdog_overflow_callback+0x118/0x120
 [<ffffffff95193dbe>] __perf_event_overflow+0xae/0x340
 [<ffffffff95192230>] ? perf_event_task_disable+0xa0/0xa0
 [<ffffffff9501a7bf>] ? x86_perf_event_set_period+0xbf/0x150
 [<ffffffff95194be4>] perf_event_overflow+0x14/0x20
 [<ffffffff95020676>] intel_pmu_handle_irq+0x206/0x410
 [<ffffffff9501966b>] perf_event_nmi_handler+0x2b/0x50
 [<ffffffff95007bb2>] nmi_handle+0xd2/0x390
 [<ffffffff95007ae5>] ? nmi_handle+0x5/0x390
 [<ffffffff958489b0>] ? _raw_spin_lock_irqsave+0x80/0x90
 [<ffffffff950080a2>] default_do_nmi+0x72/0x1c0
 [<ffffffff950082a8>] do_nmi+0xb8/0x100
 [<ffffffff9584b9aa>] end_repeat_nmi+0x1e/0x2e
 [<ffffffff958489b0>] ? _raw_spin_lock_irqsave+0x80/0x90
 [<ffffffff958489b0>] ? _raw_spin_lock_irqsave+0x80/0x90
 [<ffffffff958489b0>] ? _raw_spin_lock_irqsave+0x80/0x90
 <<EOE>>  <IRQ>  [<ffffffff95101685>] lock_hrtimer_base.isra.18+0x25/0x50
 [<ffffffff951019d3>] hrtimer_try_to_cancel+0x33/0x1f0

Quoted 1 line

Ah that one got fixed in the merge window and in -stable, right?

If that's true, that changes everything, and this might be more bisectable. I did the test above on 3.17, but perhaps I should try a run on 3.17.3

Quoted 4 lines · Vivek Goyal

I am wondering may be in some cases we panic in second kernel and sit there. Probably we should append a kernel command line automatically say "panic=1" so that it reboots itself if second kernel panics.

Quoted 4 lines

By any chance, have you enabled "CONFIG_RANDOMIZE_BASE"? If yes, please disable that as currently kexec/kdump stuff does not work with it. And it hangs very early in the boot process and I had to hook serial console to get following message on console.

I did have that enabled. (Perhaps the kconfig should conflict?)

After rebuilding without it, this..

Quoted 7 lines

Quoted 7 lines

dracut: *** Stripping files done ***
dracut: *** Store current command line parameters ***
dracut: *** Creating image file ***
dracut: *** Creating image file done ***
kdumpctl: cat: write error: Broken pipe
kdumpctl: kexec: failed to load kdump kernel
kdumpctl: Starting kdump: [FAILED]

went away. It generated the image, and things looked good. I did echo c > /proc/sysrq-trigger and got this..

SysRq : Trigger a crash

BUG: sleeping function called from invalid context at arch/x86/mm/fault.c:1192
in_atomic(): 0, irqs_disabled(): 0, pid: 8860, name: bash
3 locks held by bash/8860:
 #0:  (sb_writers#5){......}, at: [<ffffffff811eac13>] vfs_write+0x1b3/0x1f0
 #1:  (rcu_read_lock){......}, at: [<ffffffff8144a435>] __handle_sysrq+0x5/0x1b0
 #2:  (&mm->mmap_sem){......}, at: [<ffffffff8103cb20>] __do_page_fault+0x140/0x600

Preemption disabled at:[<ffffffff817ca332>] printk+0x5c/0x72

CPU: 1 PID: 8860 Comm: bash Not tainted 3.18.0-rc5+ #95 [loadavg: 0.54 0.24 0.09 2/143 8909]
 00000000000004a8 00000000e1f75c1b ffff880236473c28 ffffffff817ce5c7
 0000000000000000 0000000000000000 ffff880236473c58 ffffffff8109af8a
 ffff880236473c58 0000000000000029 0000000000000000 ffff880236473d88
Call Trace:
 [<ffffffff817ce5c7>] dump_stack+0x4f/0x7c
 [<ffffffff8109af8a>] __might_sleep+0x12a/0x190
 [<ffffffff8103cb3b>] __do_page_fault+0x15b/0x600
 [<ffffffff811613b2>] ? irq_work_queue+0x62/0xd0
 [<ffffffff8137ad7d>] ? trace_hardirqs_off_thunk+0x3a/0x3f
 [<ffffffff8103cfec>] do_page_fault+0xc/0x10
 [<ffffffff817dbcf2>] page_fault+0x22/0x30
 [<ffffffff817ca332>] ? printk+0x5c/0x72
 [<ffffffff81449ce6>] ? sysrq_handle_crash+0x16/0x20
 [<ffffffff8144a567>] __handle_sysrq+0x137/0x1b0
 [<ffffffff8144a435>] ? __handle_sysrq+0x5/0x1b0
 [<ffffffff8144aa4a>] write_sysrq_trigger+0x4a/0x50
 [<ffffffff81259f2d>] proc_reg_write+0x3d/0x80
 [<ffffffff811eab1a>] vfs_write+0xba/0x1f0
 [<ffffffff811eb628>] SyS_write+0x58/0xd0
 [<ffffffff817da052>] system_call_fastpath+0x12/0x17
Oops: 0002 [#1] PREEMPT SMP DEBUG_PAGEALLOC
CPU: 1 PID: 8860 Comm: bash Not tainted 3.18.0-rc5+ #95 [loadavg: 0.54 0.24 0.09 1/143 8909]
task: ffff8800a1a60000 ti: ffff880236470000 task.ti: ffff880236470000
RIP: 0010:[<ffffffff81449ce6>]  [<ffffffff81449ce6>] sysrq_handle_crash+0x16/0x20
RSP: 0018:ffff880236473e38  EFLAGS: 00010246
RAX: 000000000000000f RBX: ffffffff81cb4a00 RCX: 0000000000000000
RDX: 0000000000000000 RSI: ffffffff817ca332 RDI: 0000000000000063
RBP: ffff880236473e38 R08: 0000000000000001 R09: 0000000000000001
R10: 0000000000000358 R11: 0000000000000357 R12: 0000000000000063
R13: 0000000000000000 R14: 0000000000000007 R15: 0000000000000000
FS:  00007fc652f4e740(0000) GS:ffff880244200000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 0000000000000000 CR3: 000000023a3b2000 CR4: 00000000001407e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Stack:
 ffff880236473e78 ffffffff8144a567 ffffffff8144a435 0000000000000002
 0000000000000002 00007fc652f51000 0000000000000002 ffff880236473f48
 ffff880236473ea8 ffffffff8144aa4a 0000000000000002 00007fc652f51000
Call Trace:
 [<ffffffff8144a567>] __handle_sysrq+0x137/0x1b0
 [<ffffffff8144a435>] ? __handle_sysrq+0x5/0x1b0
 [<ffffffff8144aa4a>] write_sysrq_trigger+0x4a/0x50
 [<ffffffff81259f2d>] proc_reg_write+0x3d/0x80
 [<ffffffff811eab1a>] vfs_write+0xba/0x1f0
 [<ffffffff811eb628>] SyS_write+0x58/0xd0
 [<ffffffff817da052>] system_call_fastpath+0x12/0x17
Code: 01 f4 45 39 a5 b4 00 00 00 75 e2 4c 89 ef e8 d2 f7 ff ff eb d8 0f 1f 44 00 00 55 c7 05 08 b7 7e 00 01 00 00 00 48 89 e5 0f ae f8 <c6> 04 25 00 00 00 00 01 5d c3 0f 1f 44 00 00 55 31 c0 48 89 e5 
RIP  [<ffffffff81449ce6>] sysrq_handle_crash+0x16/0x20
 RSP <ffff880236473e38>

CR2: 0000000000000000

Which, asides from the sleeping while atomic thing which isn't important, does what I expected. Shortly later, it rebooted.

And then /var/crash was empty.

Quoted 4 lines · Vivek Goyal

I am wondering may be in some cases we panic in second kernel and sit there. Probably we should append a kernel command line automatically say "panic=1" so that it reboots itself if second kernel panics.

Quoted 4 lines

By any chance, have you enabled "CONFIG_RANDOMIZE_BASE"? If yes, please disable that as currently kexec/kdump stuff does not work with it. And it hangs very early in the boot process and I had to hook serial console to get following message on console.

I did have that enabled. (Perhaps the kconfig should conflict?)

Can we try following and retry and see if some additional messages show up on console and help us narrow down the problem.

- Enable verbose boot messages. CONFIG_X86_VERBOSE_BOOTUP=y

- Enable early printk in second kernel. (earlyprintk=ttyS0,115200).

You can either enable early printk in first kernel and reboot. That way second kernel will automatically have it enabled. Or you can edit "/etc/sysconfig/kdump" and append earlyprintk=<> to KDUMP_COMMANDLINE_APPEND. You will need to restart kdump service after this.

- Enable some debug output during runtime from kexec purgatory. For that one needs to pass additional arguments to /sbin/kexec. You can edit /etc/sysconfig/kdump file and modify "KEXEC_ARGS" to pass additional arguments to /sbin/kexec during kernel load. I use following for my serial console.

  KEXEC_ARGS="--console-serial --serial=0x3f8 --serial-baud=115200"

You will need to restart kdump service.

From my reading of the kexec man page, it doesn't look like I can tell

Disabling CONTEXT_TRACKING didn't change the problem. Unfortunatly the full trace didn't make it over usb-serial this time. Grr.

Here's what came over serial..

NMI watchdog: BUG: soft lockup - CPU#2 stuck for 22s! [trinity-c35:11634]

RIP: 0010:[<ffffffff88379605>]  [<ffffffff88379605>] copy_user_enhanced_fast_string+0x5/0x10
RAX: ffff880220eb4000 RBX: ffffffff887dac64 RCX: 0000000000006a18
RDX: 000000000000e02f RSI: 00007f766f466620 RDI: ffff88016f6a7617
RBP: ffff880220eb7f78 R08: 8000000000000063 R09: 0000000000000004
Call Trace:
 [<ffffffff882f4225>] ? SyS_add_key+0xd5/0x240
 [<ffffffff8837adae>] ? trace_hardirqs_on_thunk+0x3a/0x3f
 [<ffffffff887da092>] system_call_fastpath+0x12/0x17

You know what? I'm seriously starting to think that these bugs aren't actually real. Or rather, I don't think it's really a true softlockup, because most of them seem to happen in totally harmless code.

So I'm wondering whether the real issue might not be just this:

   [loadavg: 164.79 157.30 155.90 37/409 11893]

together with possibly a scheduler issue and/or a bug in the smpboot thread logic (that the watchdog uses) or similar.

That's *especially* true if it turns out that the 3.17 problem you saw was actually a perf bug that has already been fixed and is in stable. We've been looking at kernel/smp.c changes, and looking for x86 IPI or APIC changes, and found some harmlessly (at least on x86) suspicious code and this exercise might be worth it for that reason, but what if it's really just a scheduler regression.

There's been a *lot* more scheduler changes since 3.17 than the small things we've looked at for x86 entry or IPI handling. And the scheduler changes have been about things like overloaded scheduling groups etc, and I could easily imaging that some bug *there* ends up causing the watchdog process not to schedule.

Right, while it is wrong it does not explain the wreckage on 3.17, which does not have that code.

Quoted 7 lines · Dave Jones

Disabling CONTEXT_TRACKING didn't change the problem. Unfortunatly the full trace didn't make it over usb-serial this time. Grr.

Here's what came over serial..

NMI watchdog: BUG: soft lockup - CPU#2 stuck for 22s! [trinity-c35:11634]

Quoted 8 lines

RIP: 0010:[<ffffffff88379605>]  [<ffffffff88379605>] copy_user_enhanced_fast_string+0x5/0x10
RAX: ffff880220eb4000 RBX: ffffffff887dac64 RCX: 0000000000006a18
RDX: 000000000000e02f RSI: 00007f766f466620 RDI: ffff88016f6a7617
RBP: ffff880220eb7f78 R08: 8000000000000063 R09: 0000000000000004
Call Trace:
 [<ffffffff882f4225>] ? SyS_add_key+0xd5/0x240
 [<ffffffff8837adae>] ? trace_hardirqs_on_thunk+0x3a/0x3f
 [<ffffffff887da092>] system_call_fastpath+0x12/0x17

Ok, that's just about half-way in a ~57kB memory copy (you can see it in the register state: %rdx contains the original size of the key payload, rcx contains the current remaining size: 57kB total, 27kB left).

And it's holding absolutely zero locks, and not even doing anything odd. It wasn't doing anything particularly odd before either, although the kmalloc() of a 64kB area might just have caused a fair amount of VM work, of course.

You know what? I'm seriously starting to think that these bugs aren't actually real. Or rather, I don't think it's really a true softlockup, because most of them seem to happen in totally harmless code.

So I'm wondering whether the real issue might not be just this:

   [loadavg: 164.79 157.30 155.90 37/409 11893]

together with possibly a scheduler issue and/or a bug in the smpboot thread logic (that the watchdog uses) or similar.

That's *especially* true if it turns out that the 3.17 problem you saw was actually a perf bug that has already been fixed and is in stable. We've been looking at kernel/smp.c changes, and looking for x86 IPI or APIC changes, and found some harmlessly (at least on x86) suspicious code and this exercise might be worth it for that reason, but what if it's really just a scheduler regression.

There's been a *lot* more scheduler changes since 3.17 than the small things we've looked at for x86 entry or IPI handling. And the scheduler changes have been about things like overloaded scheduling groups etc, and I could easily imaging that some bug *there* ends up causing the watchdog process not to schedule.

Hmm? Scheduler people?

Linus

Just for clarification, softlockups are processes hogging the cpu (thus blocking the high priority per-cpu watchdog thread).

Quoted 7 lines · Frederic Weisbecker

Quoted 2 lines

Are we talking about different per cpu allocators here or am I missing something completely non obvious?

That's the same allocator yeah. So if the whole memory is dereferenced, faults shouldn't happen indeed.

Maybe that was a bug a few years ago but not anymore.

It has been always like that tho. Percpu memory given out is always populated and cleared.

Quoted 2 lines

Is it possible that, somehow, some part isn't zeroed by pcpu_alloc()? After all it's allocated with vzalloc() so that part could be skipped. The memset(0)

The vzalloc call is for the internal allocation bitmap not the actual percpu memory area. The actual address areas for percpu memory are obtained using pcpu_get_vm_areas() call and later get populated using map_kernel_range_noflush() (flush is performed after mapping is complete).

Trying to remember what happens with vmalloc_fault(). Ah okay, so when a new PUD gets created for vmalloc area, we don't go through all PGDs and update them. The PGD entries get faulted in lazily. Percpu memory allocator clearing or not clearing the allocated area doesn't have anything to do with it. The memory area is always fully populated in the kernel page table. It's just that the population happened while a different PGD was active and this PGD hasn't been populated with the new PUD yet.

So, yeap, vmalloc_fault() can always happen when accessing vmalloc areas and the only way to avoid that would be removing lazy PGD population - going through all PGDs and populating new PUDs immediately.

Quoted 21 lines · Tejun Heo

Quoted 7 lines · Frederic Weisbecker

Quoted 2 lines

Are we talking about different per cpu allocators here or am I missing something completely non obvious?

That's the same allocator yeah. So if the whole memory is dereferenced, faults shouldn't happen indeed.

Maybe that was a bug a few years ago but not anymore.

It has been always like that tho. Percpu memory given out is always populated and cleared.

Quoted 2 lines

Is it possible that, somehow, some part isn't zeroed by pcpu_alloc()? After all it's allocated with vzalloc() so that part could be skipped. The memset(0)

The vzalloc call is for the internal allocation bitmap not the actual percpu memory area. The actual address areas for percpu memory are obtained using pcpu_get_vm_areas() call and later get populated using map_kernel_range_noflush() (flush is performed after mapping is complete).

Quoted 8 lines

Trying to remember what happens with vmalloc_fault(). Ah okay, so when a new PUD gets created for vmalloc area, we don't go through all PGDs and update them. The PGD entries get faulted in lazily. Percpu memory allocator clearing or not clearing the allocated area doesn't have anything to do with it. The memory area is always fully populated in the kernel page table. It's just that the population happened while a different PGD was active and this PGD hasn't been populated with the new PUD yet.

It's completely undocumented behaviour, whether it has been that way for ever or not. And I agree with Fredric, that it is insane. Actuallu it's beyond insane, really.

Quoted 4 lines

So, yeap, vmalloc_fault() can always happen when accessing vmalloc areas and the only way to avoid that would be removing lazy PGD population - going through all PGDs and populating new PUDs immediately.

There is no requirement to go through ALL PGDs and populate that stuff immediately.

Lets look at the two types of allocations

1) Kernel percpu allocations

2) Per process/task percpu allocations

Of course we do not have a way to distinguish those, but we really should have one.

#1 Kernel percpu allocations usually happen in the context of driver
bringup, subsystem initialization, interrupt setup etc.

So this is functionality which is not a hotpath and usually requires some form of synchronization versus the rest of the system anyway.

The per cpu population stuff is serialized with a mutex anyway, so what's wrong to have a globaly visible percpu sequence counter, which is incremented whenever a new allocation is populated or torn down?

We can make that sequence counter a per cpu variable as well to avoid the issues of a global variable (preferrably that's a compile/boot time allocated percpu variable to avoid the obvious circulus vitiosus)

Now after that increment the allocation side needs to wait for a scheduling cycle on all cpus (we have mechanisms for that)

So in the scheduler if the same task gets reselected you check that sequence count and update the PGD if different. If a task switch happens then you also need to check the sequence count and act accordingly.

If we make the sequence counter a percpu variable as outlined above the overhead of checking this is just noise versus the other nonsense we do in schedule().

#2 That's process related statistics and instrumentation stuff.

Now that just needs a immediate population on the process->mm->pgd aside of the init_mm.pgd, but that's really not a big deal.

Of course that does not solve the issues we have with the current infrastructure retroactively, but it allows us to avoid fuckups like the one Frederic was talking about that perf invented its own kmalloc based 'percpu' replacement just to workaround the shortcoming in a particular place.

What really frightens me is the potential and well hidden fuckup potential which lurks around the corner and the hard to debug once in a while fallout which might be caused by this.

Quoted 3 lines · Thomas Gleixner

Right, while it is wrong it does not explain the wreckage on 3.17, which does not have that code.

Thomas, I'm currently going off the assumption that I'll see this from the x86 trees, and I can ignore the patch. It doesn't seem like this is a particularly pressing bug.

If it's *not* going to show up as a pull request, holler, and I'll just apply it.

It's completely undocumented behaviour, whether it has been that way for ever or not. And I agree with Fredric, that it is insane. Actuallu it's beyond insane, really.

So in the scheduler if the same task gets reselected you check that sequence count and update the PGD if different. If a task switch happens then you also need to check the sequence count and act accordingly.

What really frightens me is the potential and well hidden fuckup potential which lurks around the corner and the hard to debug once in a while fallout which might be caused by this.

Quoted 3 lines · Thomas Gleixner

It's completely undocumented behaviour, whether it has been that way for ever or not. And I agree with Fredric, that it is insane. Actuallu it's beyond insane, really.

This is exactly the same for any address in the vmalloc space.

..

Quoted 4 lines

So in the scheduler if the same task gets reselected you check that sequence count and update the PGD if different. If a task switch happens then you also need to check the sequence count and act accordingly.

That isn't enough tho. What if the percpu allocated pointer gets passed to another CPU without task switching? You'd at least need to send IPIs to all CPUs so that all the active PGDs get updated synchronously.

Quoted 3 lines

What really frightens me is the potential and well hidden fuckup potential which lurks around the corner and the hard to debug once in a while fallout which might be caused by this.

Lazy vmalloc population through fault is something we accepted as reasonable as it works fine for most of the kernel.

For the time being, we can make percpu accessors complain when called from nmi handlers so that the problematic ones can be easily identified.

Quoted 6 lines · Tejun Heo

Quoted 3 lines · Thomas Gleixner

It's completely undocumented behaviour, whether it has been that way for ever or not. And I agree with Fredric, that it is insane. Actuallu it's beyond insane, really.

This is exactly the same for any address in the vmalloc space.

I know, but I really was not aware of the fact that dynamically allocated percpu stuff is vmalloc based and therefor exposed to the same issues.

The normal vmalloc space simply does not have the problems which are generated by percpu allocations which have no documented access restrictions.

You created a special case and that special case is clever but not very well thought out considering the use cases of percpu variables and the completely undocumented limitations you introduced silently.

Just admit it and dont try to educate me about trivial vmalloc properties.

Quoted 4 lines

That isn't enough tho. What if the percpu allocated pointer gets passed to another CPU without task switching? You'd at least need to send IPIs to all CPUs so that all the active PGDs get updated synchronously.

You obviously did not even take the time to carefully read what I wrote:

"Now after that increment the allocation side needs to wait for a
scheduling cycle on all cpus (we have mechanisms for that)"

That's exactly stating what you claim to be 'not enough'.

Quoted 3 lines

For the time being, we can make percpu accessors complain when called from nmi handlers so that the problematic ones can be easily identified.

You should have done that in the very first place instead of letting other people run into issues which you should have thought of from the very beginning.

Hello,

Quoted 16 lines · Thomas Gleixner

Quoted 6 lines · Tejun Heo

Quoted 3 lines · Thomas Gleixner

It's completely undocumented behaviour, whether it has been that way for ever or not. And I agree with Fredric, that it is insane. Actuallu it's beyond insane, really.

This is exactly the same for any address in the vmalloc space.

I know, but I really was not aware of the fact that dynamically allocated percpu stuff is vmalloc based and therefor exposed to the same issues.

The normal vmalloc space simply does not have the problems which are generated by percpu allocations which have no documented access restrictions.

Quoted 6 lines

You created a special case and that special case is clever but not very well thought out considering the use cases of percpu variables and the completely undocumented limitations you introduced silently.

Just admit it and dont try to educate me about trivial vmalloc properties.

Why are you always so overly dramatic? How is this productive? Sure, this could have been better but I missed it at the beginning and this is the first time I hear about this issue. Shits happen and we fix them.

Quoted 5 lines

Quoted 4 lines

That isn't enough tho. What if the percpu allocated pointer gets passed to another CPU without task switching? You'd at least need to send IPIs to all CPUs so that all the active PGDs get updated synchronously.

Quoted 7 lines

You obviously did not even take the time to carefully read what I wrote:

"Now after that increment the allocation side needs to wait for a
scheduling cycle on all cpus (we have mechanisms for that)"

That's exactly stating what you claim to be 'not enough'.

Missed that. Sorry.

Quoted 7 lines

Quoted 3 lines

For the time being, we can make percpu accessors complain when called from nmi handlers so that the problematic ones can be easily identified.

You should have done that in the very first place instead of letting other people run into issues which you should have thought of from the very beginning.

Sure, it would have been better if I noticed that from the get-go, but I couldn't think of the NMI case that time and neither did anybody who reviewed the code. It'd be awesome if we could have avoided it but it didn't go that way, so let's fix it. Can we please stay technical?

So, for now, all we need is adding nmi check in percpu accessors, right?

What's the issue with nmi? Page faults are supposed to nest correctly inside nmi, right?

Quoted 3 lines

So, for now, all we need is adding nmi check in percpu accessors, right?

What's the issue with nmi? Page faults are supposed to nest correctly inside nmi, right?

Quoted 4 lines · Andy Lutomirski

Quoted 3 lines

So, for now, all we need is adding nmi check in percpu accessors, right?

Quoted 2 lines

What's the issue with nmi? Page faults are supposed to nest correctly inside nmi, right?

Thought they couldn't. Looking at the trace that Frederic linked, it looks like straight-out tracing function recursion due to an unexpected fault while holding a lock. I don't think this can be annotated from percpu accessor side. There's nothing special about the context. :(

Quoted 16 lines · Thomas Gleixner

Quoted 6 lines · Tejun Heo

Quoted 3 lines · Thomas Gleixner

It's completely undocumented behaviour, whether it has been that way for ever or not. And I agree with Fredric, that it is insane. Actuallu it's beyond insane, really.

This is exactly the same for any address in the vmalloc space.

I know, but I really was not aware of the fact that dynamically allocated percpu stuff is vmalloc based and therefor exposed to the same issues.

The normal vmalloc space simply does not have the problems which are generated by percpu allocations which have no documented access restrictions.

Quoted 6 lines

You created a special case and that special case is clever but not very well thought out considering the use cases of percpu variables and the completely undocumented limitations you introduced silently.

Just admit it and dont try to educate me about trivial vmalloc properties.

Why are you always so overly dramatic?

Quoted 1 line

Quoted 1 line

This is exactly the same for any address in the vmalloc space.

How is this productive?

Sure, this could have been better but I missed it at the beginning and this is the first time I hear about this issue.

Shits happen and we fix them.

Quoted 8 lines

Quoted 4 lines

That isn't enough tho. What if the percpu allocated pointer gets passed to another CPU without task switching? You'd at least need to send IPIs to all CPUs so that all the active PGDs get updated synchronously.

You obviously did not even take the time to carefully read what I wrote:

Quoted 4 lines

"Now after that increment the allocation side needs to wait for a
scheduling cycle on all cpus (we have mechanisms for that)"

That's exactly stating what you claim to be 'not enough'.

Missed that. Sorry.

So, for now, all we need is adding nmi check in percpu accessors, right?

Quoted 4 lines · Andy Lutomirski

Quoted 3 lines

So, for now, all we need is adding nmi check in percpu accessors, right?

Quoted 2 lines

What's the issue with nmi? Page faults are supposed to nest correctly inside nmi, right?

Thought they couldn't. Looking at the trace that Frederic linked, it looks like straight-out tracing function recursion due to an unexpected fault while holding a lock. I don't think this can be annotated from percpu accessor side. There's nothing special about the context. :(

Does this matter for anybody other than tracers? Ultimately, the solution would be removing the vmalloc area faulting as Thomas suggested.

[...]

That's *especially* true if it turns out that the 3.17 problem you saw was actually a perf bug that has already been fixed and is in stable. We've been looking at kernel/smp.c changes, and looking for x86 IPI or APIC changes, and found some harmlessly (at least on x86) suspicious code and this exercise might be worth it for that reason, but what if it's really just a scheduler regression.

There's been a *lot* more scheduler changes since 3.17 than the small things we've looked at for x86 entry or IPI handling. And the scheduler changes have been about things like overloaded scheduling groups etc, and I could easily imaging that some bug *there* ends up causing the watchdog process not to schedule.

Hmm? Scheduler people?

Quoted 18 lines · Vivek Goyal

Can we try following and retry and see if some additional messages show up on console and help us narrow down the problem.

- Enable verbose boot messages. CONFIG_X86_VERBOSE_BOOTUP=y

- Enable early printk in second kernel. (earlyprintk=ttyS0,115200).

You can either enable early printk in first kernel and reboot. That way second kernel will automatically have it enabled. Or you can edit "/etc/sysconfig/kdump" and append earlyprintk=<> to KDUMP_COMMANDLINE_APPEND. You will need to restart kdump service after this.

- Enable some debug output during runtime from kexec purgatory. For that one needs to pass additional arguments to /sbin/kexec. You can edit /etc/sysconfig/kdump file and modify "KEXEC_ARGS" to pass additional arguments to /sbin/kexec during kernel load. I use following for my serial console.

Quoted 3 lines

  KEXEC_ARGS="--console-serial --serial=0x3f8 --serial-baud=115200"

You will need to restart kdump service.

The only serial port on this machine is usb serial, which doesn't have io ports.

From my reading of the kexec man page, it doesn't look like I can tell it to use ttyUSB0.

And because it relies on usb being initialized, this probably isn't going to help too much with early boot.

earlyprintk=tty0 didn't show anything extra after the sysrq-c oops. likewise, =ttyUSB0

I'm going to try bisecting the problem I'm debugging again, so I'm not going to dig into this much more today.

Quoted 2 lines · Tejun Heo

Sure, this could have been better but I missed it at the beginning and this is the first time I hear about this issue.

So the issues Frederic talked about in that very thread about recursive faults and the need that perf had to emulate percpu stuff in order to work around them have never been communicated to you?

I that's the case then that's not your problem, but a serious problem in our overall process.

It might make sense to disable the softlockup detector altogether and just see whether trinity finishes/wedges, whether a login over the console is still possible - etc.

The softlockup messages in themselves are only analytical, unless CONFIG_BOOTPARAM_SOFTLOCKUP_PANIC_VALUE=1 is used.

So when the issue arised 4 years ago, it was a problem only for NMIs. Like Linus says: "what happens in NMI stays in NMI". Ok no that's not quite what he says :-) But NMIs happen to be a corner case for about everything and it's sometimes better to fix things from NMI itself, or have an NMI special case rather than grow the whole infrastructure in complexity to support this very corner case.

That doesn't appear to have anything to with nmi though, right?

Wouldn't this issue be fixed by moving the vmalloc_fault check into do_page_fault before exception_enter?

Hello, Andy.

Quoted 1 line · Andy Lutomirski

That doesn't appear to have anything to with nmi though, right?

I thought that was the main offender but, apparently, not any more.

Quoted 2 lines

Wouldn't this issue be fixed by moving the vmalloc_fault check into do_page_fault before exception_enter?

Can you please elaborate why that'd fix the issue? I'm not intimiately familiar with the fault handling so it'd be great if you can give me some pointers in terms of where to look at.

Thanks.

--
tejun

If you move the vmalloc fixup before exception_enter() and return if the fault was from vmalloc, then you can't recurse. You need to be careful not to touch anything that uses RCU before exception_enter, though.

* Static percpu areas wouldn't trigger fault lazily. Note that this is not necessarily because the first percpu chunk which contains the static area is embedded inside the kernel linear mapping. Depending on the memory layout and boot param, percpu allocator may choose to map the first chunk in vmalloc space too; however, this still works out fine because at that point there are no other page tables and the PUD entries covering the first chunk is faulted in before other pages tables are copied from the kernel one.

* NMI used to be a problem because vmalloc fault handler couldn't safely nest inside NMI handler but this has been fixed since and it should work fine from NMI handlers now.

* Function tracers are problematic because they may end up nesting inside themselves through triggering a vmalloc fault while accessing dynamic percpu memory area. This may lead to recursive locking and other surprises.

Are there other cases where the lazy vmalloc faults can break things?

(The 64-bit mode also has a "WARN_ON_ONCE(in_nmi())", which I guess is good - but it's good because the 64-bit version is written the way it is).

Looking at kernel/trace/trace_functions.c: function_trace_call() which is registered with RECURSION_SAFE, I see that the recursion check is done before the per_cpu_ptr() call to the dynamically allocated per_cpu data.

It looks OK, but...

Oh! but if we trace the page fault handler, and we fault here too we just nuked the cr2 register. Not good.

Actually, in_nmi() is now safe for vmalloc faults. In fact, it handles the clobbering of the cr2 register just fine.

Quoted 3 lines · Steven Rostedt

Actually, in_nmi() is now safe for vmalloc faults. In fact, it handles the clobbering of the cr2 register just fine.

That's not what I object to and find incorrect wrt NMI.

Compare the simple and correct 32-bit code to the complex and incorrect 64-bit code.

In particular, look at how the 32-bit code relies *entirely* on hardware state.

Then look at where the 64-bit code does not.

Quoted 3 lines · Steven Rostedt

Actually, in_nmi() is now safe for vmalloc faults. In fact, it handles the clobbering of the cr2 register just fine.

That's not what I object to and find incorrect wrt NMI.

Compare the simple and correct 32-bit code to the complex and incorrect 64-bit code.

In particular, look at how the 32-bit code relies *entirely* on hardware state.

Then look at where the 64-bit code does not.

Both mystify me. Why does the 32-bit version walk down the hierarchy at all instead of just touching the top level?

I see. You have issues with the use of current->active_mm instead of just doing a read_cr3() (and I'm sure other things).

Quoted 3 lines · Andy Lutomirski

Both mystify me. Why does the 32-bit version walk down the hierarchy at all instead of just touching the top level?

Quite frankly, I think it's just due to historical reasons, and should be removed.

But the historical reasons are that with the aliasing of the PUD and PMD entries in the PGD, it's all fairly confusing. So I think we only used to do the top level, but then when we expanded from two levels to three, that "top level" became the pmd, and then when we expanded from three to four, the pmd was actually two levels down. So it's all basically mindless work.

So I do think we could simplify and unify things.

In 32-bit mode, we actually have two different cases:

- in PAE, there's the magic top-level 4-entry PGD that always *has*
to be present (the P bit isn't actually checked by hardware)

As a result, in PAE mode, the top PGD entries always exist, and
are always prepopulated, and for the kernel area (including obviously the vmalloc space) always points to the init_pgd[] entry.

Ergo, in PAE mode, I don't think we should ever hit this case in
the first place.

- in non-PAE mode, we should just copy the top-level entry, and return.

And in 64-bit more, we only have the "copy the top-level entry" case.

So I think we should

(a) remove the 32-bit vs 64-bit difference, because that's not actually valid

(b) make it a PAE vs non-PAE difference

(c) the PAE case is a no-op

(d) the non-PAE case would look something like this:

    static noinline int vmalloc_fault(unsigned long address)
    {
        unsigned index;
        pgd_t *pgd_dst, pgd_entry;

        /* Make sure we are in vmalloc area: */
        if (!(address >= VMALLOC_START && address < VMALLOC_END))
                return -1;

        index = pgd_index(address);
        pgd_entry = init_mm.pgd[index];
        if (!pgd_present(pgd_entry))
                return -1;

        pgd_dst = __va(PAGE_MASK & read_cr3());
        if (pgd_present(pgd_dst[index]))
                return -1;

        ACCESS_ONCE(pgd_dst[index]) = pgd_entry;
        return 0;
    }
    NOKPROBE_SYMBOL(vmalloc_fault);

and it's done.

Would anybody be willing to actually *test* something like the above? The above may compile, but that's all the "testing" it got.

(d) the non-PAE case would look something like this:

    static noinline int vmalloc_fault(unsigned long address)
    {
        unsigned index;
        pgd_t *pgd_dst, pgd_entry;

        /* Make sure we are in vmalloc area: */
        if (!(address >= VMALLOC_START && address < VMALLOC_END))
                return -1;

  static noinline int vmalloc_fault(unsigned long address)
  {
        pgd_t *pgd_dst;
        pgdval_t pgd_entry;
        unsigned index = pgd_index(address);

        if (index < KERNEL_PGD_BOUNDARY)
                return -1;

        pgd_entry = init_mm.pgd[index].pgd;
        if (!pgd_entry)
                return -1;

        pgd_dst = __va(PAGE_MASK & read_cr3());
        pgd_dst += index;

        if (pgd_dst->pgd)
                return -1;

        ACCESS_ONCE(pgd_dst->pgd) = pgd_entry;
        return 0;

}
NOKPROBE_SYMBOL(vmalloc_fault);

Hmm? Does anybody see anything fundamentally wrong with this?

Linus

Should we at least check to see if it is present?

        if (!(pgd_entry & 1))
                return -1;

So I kind of agree, but it wouldn't be my primary worry. My primary worry is actually paravirt doing something insane.

Here's the simplified end result. Again, this is TOTALLY UNTESTED. I compiled it and verified that the code generation looks like what I'd have expected, but that's literally it.

  static noinline int vmalloc_fault(unsigned long address)
  {
        pgd_t *pgd_dst;
        pgdval_t pgd_entry;
        unsigned index = pgd_index(address);

        if (index < KERNEL_PGD_BOUNDARY)
                return -1;

        pgd_entry = init_mm.pgd[index].pgd;
        if (!pgd_entry)
                return -1;

        pgd_dst = __va(PAGE_MASK & read_cr3());
        pgd_dst += index;

        if (pgd_dst->pgd)
                return -1;

        ACCESS_ONCE(pgd_dst->pgd) = pgd_entry;

Quoted 3 lines · Linus Torvalds

So I kind of agree, but it wouldn't be my primary worry. My primary worry is actually paravirt doing something insane.

Btw, on that tangent, does anybody actually care about paravirt any more?

I'd love to start moving away from it. It makes a lot of the low-level code completely impossible to follow due to the random indirection through "native" vs "paravirt op table". Not just the page table handling, it's all over.

Anybody who seriously does virtualization uses hw virtualization that is much better than it used to be. And the non-serious users aren't that performance-sensitive by definition.

I note that the Fedora kernel config seems to include paravirt by default, so you get a lot of the crazy overheads..

This will break paravirt. set_pgd/set_pmd are paravirt functions.

Anybody who seriously does virtualization uses hw virtualization that is much better than it used to be. And the non-serious users aren't that performance-sensitive by definition.

I note that the Fedora kernel config seems to include paravirt by default, so you get a lot of the crazy overheads..

Quoted 6 lines · Linus Torvalds

Anybody who seriously does virtualization uses hw virtualization that is much better than it used to be. And the non-serious users aren't that performance-sensitive by definition.

I note that the Fedora kernel config seems to include paravirt by default, so you get a lot of the crazy overheads..

I'm not sure how many people actually use paravirt these days, but the reason Fedora has it enabled still at least is probably because..

config KVM_GUEST
bool "KVM Guest support (including kvmclock)" depends on PARAVIRT

But tbh I've not looked at this stuff since it first got merged. Will a full-virt system kvm boot a guest without KVM_GUEST enabled ? (ie, is this just an optimisation for the paravirt case?)

I'm not a heavy virt user, so I don't even remember how a lot of this stuff is supposed to work.

Dave

Quoted 8 lines · Linus Torvalds

Quoted 3 lines · Linus Torvalds

So I kind of agree, but it wouldn't be my primary worry. My primary worry is actually paravirt doing something insane.

Btw, on that tangent, does anybody actually care about paravirt any more?

Amazon, for better or for worse.

Quoted 9 lines

I'd love to start moving away from it. It makes a lot of the low-level code completely impossible to follow due to the random indirection through "native" vs "paravirt op table". Not just the page table handling, it's all over.

Anybody who seriously does virtualization uses hw virtualization that is much better than it used to be. And the non-serious users aren't that performance-sensitive by definition.

Quoted 2 lines

I note that the Fedora kernel config seems to include paravirt by default, so you get a lot of the crazy overheads..

I think that there is a move toward deprecating Xen PV in favor of PVH, but we're not there yet.

Quoted 25 lines · Andy Lutomirski

Quoted 8 lines · Linus Torvalds

Quoted 3 lines · Linus Torvalds

So I kind of agree, but it wouldn't be my primary worry. My primary worry is actually paravirt doing something insane.

Btw, on that tangent, does anybody actually care about paravirt any more?

Amazon, for better or for worse.

Quoted 11 lines

I'd love to start moving away from it. It makes a lot of the low-level code completely impossible to follow due to the random indirection through "native" vs "paravirt op table". Not just the page table handling, it's all over.

Anybody who seriously does virtualization uses hw virtualization that is much better than it used to be. And the non-serious users aren't that performance-sensitive by definition.

I note that the Fedora kernel config seems to include paravirt by default, so you get a lot of the crazy overheads..

Quoted 2 lines

I think that there is a move toward deprecating Xen PV in favor of PVH, but we're not there yet.

A move where? The Xen stuff in Fedora is ... not paid attention to very much. If there's something we should be looking at turning off (or on), we're happy to take suggestions.

josh

Quoted 2 lines · Thomas Gleixner

This will break paravirt. set_pgd/set_pmd are paravirt functions.

I suspect we could use "set_pgd()" here instead of the direct access. I didn't want to walk through all the levels to see exactly which random op I needed to use.

Quoted 29 lines · Josh Boyer

Quoted 27 lines · Andy Lutomirski

Quoted 8 lines · Linus Torvalds

Quoted 3 lines · Linus Torvalds

So I kind of agree, but it wouldn't be my primary worry. My primary worry is actually paravirt doing something insane.

Btw, on that tangent, does anybody actually care about paravirt any more?

Amazon, for better or for worse.

Quoted 11 lines

I'd love to start moving away from it. It makes a lot of the low-level code completely impossible to follow due to the random indirection through "native" vs "paravirt op table". Not just the page table handling, it's all over.

Anybody who seriously does virtualization uses hw virtualization that is much better than it used to be. And the non-serious users aren't that performance-sensitive by definition.

I note that the Fedora kernel config seems to include paravirt by default, so you get a lot of the crazy overheads..

I think that there is a move toward deprecating Xen PV in favor of PVH, but we're not there yet.

Quoted 3 lines

A move where? The Xen stuff in Fedora is ... not paid attention to very much. If there's something we should be looking at turning off (or on), we're happy to take suggestions.

A move in the Xen project. As I understand it, Xen wants to deprecate PV in favor of PVH, but PVH is still experimental.

I think that dropping PARAVIRT in Fedora might be a bad idea for several more releases, since that's likely to break the EC2 images.

I don't think that works on 32bit. See the magic in vmalloc_sync_one().

Quoted 3 lines · Thomas Gleixner

I don't think that works on 32bit. See the magic in vmalloc_sync_one().

Heh. I guess we could just add a wrapper around this crap, and make it very clear that the paravirt case is a horrible horrible hack.

Something like

   #define set_one_pgd_entry(entry,pgdp) (pgdp)->pgd = (entry)

for the regular case, and then for paravirt we do something very explicitly horrid, like

   #ifdef CONFIG_PARAVIRT
   #ifdef CONFIG_X86_32
   // The pmd is the top-level page directory on non-PAE x86, nested
inside pgd/pud
   #define set_one_pgd_entry(entry,pgdp) set_pmd((pmd_t *)(pgdp),
(pmd_t) { entry } )
   #else
   #define set_one_pgd_entry(entry, pgdp) do { set_pgd(pgdp, (pgd_t) {

entry }); arch_flush_lazy_mmu_mode(); } while (0)
#endif

because on x86-64, there seems to be that whole lazy_mode pv_ops craziness (which I'm not at all convinced is needed here, but that's what the current code does).

Quoted 9 lines · Tejun Heo

* Static percpu areas wouldn't trigger fault lazily. Note that this is not necessarily because the first percpu chunk which contains the static area is embedded inside the kernel linear mapping. Depending on the memory layout and boot param, percpu allocator may choose to map the first chunk in vmalloc space too; however, this still works out fine because at that point there are no other page tables and the PUD entries covering the first chunk is faulted in before other pages tables are copied from the kernel one.

That sounds correct.

Quoted 4 lines

* NMI used to be a problem because vmalloc fault handler couldn't safely nest inside NMI handler but this has been fixed since and it should work fine from NMI handlers now.

Right. Of course "should work fine" does not excatly mean "will work fine".

Quoted 5 lines

* Function tracers are problematic because they may end up nesting inside themselves through triggering a vmalloc fault while accessing dynamic percpu memory area. This may lead to recursive locking and other surprises.

The function tracer infrastructure now has a recursive check that happens rather early in the call. Unless the registered OPS specifically states it handles recursions (FTRACE_OPS_FL_RECUSION_SAFE), ftrace will add the necessary recursion checks. If a registered OPS lies about being recusion safe, well we can't stop suicide.

Looking at kernel/trace/trace_functions.c: function_trace_call() which is registered with RECURSION_SAFE, I see that the recursion check is done before the per_cpu_ptr() call to the dynamically allocated per_cpu data.

It looks OK, but...

Oh! but if we trace the page fault handler, and we fault here too we just nuked the cr2 register. Not good.

Quoted 27 lines · Steven Rostedt

Quoted 9 lines · Tejun Heo

* Static percpu areas wouldn't trigger fault lazily. Note that this is not necessarily because the first percpu chunk which contains the static area is embedded inside the kernel linear mapping. Depending on the memory layout and boot param, percpu allocator may choose to map the first chunk in vmalloc space too; however, this still works out fine because at that point there are no other page tables and the PUD entries covering the first chunk is faulted in before other pages tables are copied from the kernel one.

That sounds correct.

Quoted 4 lines

* NMI used to be a problem because vmalloc fault handler couldn't safely nest inside NMI handler but this has been fixed since and it should work fine from NMI handlers now.

Right. Of course "should work fine" does not excatly mean "will work fine".

Quoted 5 lines

* Function tracers are problematic because they may end up nesting inside themselves through triggering a vmalloc fault while accessing dynamic percpu memory area. This may lead to recursive locking and other surprises.

Quoted 5 lines

The function tracer infrastructure now has a recursive check that happens rather early in the call. Unless the registered OPS specifically states it handles recursions (FTRACE_OPS_FL_RECUSION_SAFE), ftrace will add the necessary recursion checks. If a registered OPS lies about being recusion safe, well we can't stop suicide.

Same if the recursion state is based on per cpu memory.

Quoted 5 lines

Looking at kernel/trace/trace_functions.c: function_trace_call() which is registered with RECURSION_SAFE, I see that the recursion check is done before the per_cpu_ptr() call to the dynamically allocated per_cpu data.

Quoted 4 lines

It looks OK, but...

Oh! but if we trace the page fault handler, and we fault here too we just nuked the cr2 register. Not good.

If we fault in the page fault handler, we double fault and apparently recovering from that isn't quite expected anyway.

Hello, Frederic.

On Fri, Nov 21, 2014 at 03:13:35PM +0100, Frederic Weisbecker wrote:
...

Quoted 6 lines

So when the issue arised 4 years ago, it was a problem only for NMIs. Like Linus says: "what happens in NMI stays in NMI". Ok no that's not quite what he says :-) But NMIs happen to be a corner case for about everything and it's sometimes better to fix things from NMI itself, or have an NMI special case rather than grow the whole infrastructure in complexity to support this very corner case.

I'm not familiar with the innards of fault handling, so can you please help me understand what may actually break? Here are what I currently understand.

* Static percpu areas wouldn't trigger fault lazily. Note that this is not necessarily because the first percpu chunk which contains the static area is embedded inside the kernel linear mapping. Depending on the memory layout and boot param, percpu allocator may choose to map the first chunk in vmalloc space too; however, this still works out fine because at that point there are no other page tables and the PUD entries covering the first chunk is faulted in before other pages tables are copied from the kernel one.

* NMI used to be a problem because vmalloc fault handler couldn't safely nest inside NMI handler but this has been fixed since and it should work fine from NMI handlers now.

* Function tracers are problematic because they may end up nesting inside themselves through triggering a vmalloc fault while accessing dynamic percpu memory area. This may lead to recursive locking and other surprises.

Are there other cases where the lazy vmalloc faults can break things?

Quoted 41 lines · Frederic Weisbecker

Quoted 27 lines · Steven Rostedt

Quoted 9 lines · Tejun Heo

* Static percpu areas wouldn't trigger fault lazily. Note that this is not necessarily because the first percpu chunk which contains the static area is embedded inside the kernel linear mapping. Depending on the memory layout and boot param, percpu allocator may choose to map the first chunk in vmalloc space too; however, this still works out fine because at that point there are no other page tables and the PUD entries covering the first chunk is faulted in before other pages tables are copied from the kernel one.

That sounds correct.

Quoted 4 lines

* NMI used to be a problem because vmalloc fault handler couldn't safely nest inside NMI handler but this has been fixed since and it should work fine from NMI handlers now.

Right. Of course "should work fine" does not excatly mean "will work fine".

Quoted 5 lines

* Function tracers are problematic because they may end up nesting inside themselves through triggering a vmalloc fault while accessing dynamic percpu memory area. This may lead to recursive locking and other surprises.

Quoted 5 lines

The function tracer infrastructure now has a recursive check that happens rather early in the call. Unless the registered OPS specifically states it handles recursions (FTRACE_OPS_FL_RECUSION_SAFE), ftrace will add the necessary recursion checks. If a registered OPS lies about being recusion safe, well we can't stop suicide.

Same if the recursion state is based on per cpu memory.

Quoted 5 lines

Looking at kernel/trace/trace_functions.c: function_trace_call() which is registered with RECURSION_SAFE, I see that the recursion check is done before the per_cpu_ptr() call to the dynamically allocated per_cpu data.

Quoted 7 lines

Quoted 4 lines

It looks OK, but...

Oh! but if we trace the page fault handler, and we fault here too we just nuked the cr2 register. Not good.

If we fault in the page fault handler, we double fault and apparently recovering from that isn't quite expected anyway.

Not quite. We only double fault if we fault while pushing the hardware part of the state onto the stack. That happens even before the entry asm gets run.

Otherwise if we have a page fault inside do_page_fault, it's just a nested page fault.

--Andy

Signature · 2 lines

Andy Lutomirski
AMA Capital Management, LLC

Quoted 6 lines · Tejun Heo

Hello, Andy.

Quoted 1 line · Andy Lutomirski

That doesn't appear to have anything to with nmi though, right?

Quoted 8 lines

I thought that was the main offender but, apparently, not any more.

Quoted 2 lines

Wouldn't this issue be fixed by moving the vmalloc_fault check into do_page_fault before exception_enter?

Can you please elaborate why that'd fix the issue? I'm not intimiately familiar with the fault handling so it'd be great if you can give me some pointers in terms of where to look at.

do_page_fault is called directly from asm. It does:

    prev_state = exception_enter();
    __do_page_fault(regs, error_code, address);
    exception_exit(prev_state);

The vmalloc fixup is in __do_page_fault.

exception_enter does various accounting and tracing things, and I think that the recursion in stack trace I saw was in exception_enter.

If you move the vmalloc fixup before exception_enter() and return if the fault was from vmalloc, then you can't recurse. You need to be careful not to touch anything that uses RCU before exception_enter, though.

Quoted 23 lines · Linus Torvalds

Here's the simplified end result. Again, this is TOTALLY UNTESTED. I compiled it and verified that the code generation looks like what I'd have expected, but that's literally it.

  static noinline int vmalloc_fault(unsigned long address)
  {
        pgd_t *pgd_dst;
        pgdval_t pgd_entry;
        unsigned index = pgd_index(address);

        if (index < KERNEL_PGD_BOUNDARY)
                return -1;

        pgd_entry = init_mm.pgd[index].pgd;
        if (!pgd_entry)
                return -1;

        pgd_dst = __va(PAGE_MASK & read_cr3());
        pgd_dst += index;

        if (pgd_dst->pgd)
                return -1;

Quoted 1 line

        ACCESS_ONCE(pgd_dst->pgd) = pgd_entry;

This will break paravirt. set_pgd/set_pmd are paravirt functions.

But I'm fine with breaking it, then you just need to change CONFIG_PARAVIRT to 'def_bool n'

Quoted 23 lines · Linus Torvalds

Here's the simplified end result. Again, this is TOTALLY UNTESTED. I compiled it and verified that the code generation looks like what I'd have expected, but that's literally it.

  static noinline int vmalloc_fault(unsigned long address)
  {
        pgd_t *pgd_dst;
        pgdval_t pgd_entry;
        unsigned index = pgd_index(address);

        if (index < KERNEL_PGD_BOUNDARY)
                return -1;

        pgd_entry = init_mm.pgd[index].pgd;
        if (!pgd_entry)
                return -1;

        pgd_dst = __va(PAGE_MASK & read_cr3());
        pgd_dst += index;

        if (pgd_dst->pgd)
                return -1;

Quoted 1 line

        ACCESS_ONCE(pgd_dst->pgd) = pgd_entry;

This will break paravirt. set_pgd/set_pmd are paravirt functions.

But I'm fine with breaking it, then you just need to change CONFIG_PARAVIRT to 'def_bool n'

Quoted 2 lines

Otherwise if we have a page fault inside do_page_fault, it's just a nested page fault.

Oh ok!

But we still have the cr2 issue that Steve talked about.

I'm fine with that. I just think it's not horrid enough, but that can be fixed easily :)

Quoted 3 lines · Thomas Gleixner

I'm fine with that. I just think it's not horrid enough, but that can be fixed easily :)

Oh, I think it's plenty horrid.

Anyway, here's an actual patch. As usual, it has seen absolutely no actual testing, but I did try to make sure it compiles and seems to do the right thing on:
- x86-32 no-PAE
- x86-32 no-PAE with PARAVIRT
- x86-32 PAE
- x86-64

also, I just removed the noise that is "vmalloc_sync_all()", since it's just all garbage and nothing actually uses it. Yeah, it's used by "register_die_notifier()", which makes no sense what-so-ever. Whatever. It's gone.

Can somebody actually *test* this? In particular, in any kind of real paravirt environment? Or, any comments even without testing?

I *really* am not proud of the mess wrt the whole

  #ifdef CONFIG_PARAVIRT
  #ifdef CONFIG_X86_32
    ...

but I think that from a long-term perspective, we're actually better off with this kind of really ugly - but very explcit - hack that very clearly shows what is going on.

The old code that actually "walked" the page tables was more "portable", but was somewhat misleading about what was actually going on.