frequent lockups in 3.18rc4

Up to the point where it exposes different instructions and completely different code pathes. I'm not agreeing with your theory that after the RT throttler hit the watchdog and everything else goes completely bonkers. And even before that happens we see a different backtrace on CPU0:

[25149.982766] RIP: 0010:[<ffffffff810cf1db>]  [<ffffffff810cf1db>] invoke_rcu_core+0x2b/0x50

Though I have to admit that this "very same instruction" pattern puzzled me for quite a while as well.

The watchdog timer runs on a fully periodic schedule. It's self rearming via

	 hrtimer_forward_now(hrtimer, ns_to_ktime(sample_period));

So if that aligns with the equally periodic tick interrupt on the other CPU then you might get into that situation due to the fully synchronizing and serializing nature of HPET reads.

That can drift apart over time because the timer device (apic or that new fangled tscdeadline timer) are not frequency corrected versus timekeeping.

That __remove_hrtimer has a '?' in front of it. So its not a reliable trace entry.

There is NO hrtimer related operation in the msgget() syscall at all and SyS_msgget() is the only reliable entry on that stack trace.

So that __remove_hrtimer operation happened before that msgget() syscall and is just a stack artifact. poll/select/nanosleep whatever.

hrtimers overflow in about 584 years

No. I did not dismiss it because HPET is making progress. I looked at it from a different angle.

So lets assume there is that hrtimer_remove race (I'm certainly going to stare at that tomorrow with fully awake brain. It's past beer o'clock here). How do you explain that:

1) the watchdog always triggers on CPU1?

2) the race only ever happens on CPU0?

3) the hrtimer interrupt took too long message never appears?

If that timer interrupt loops forever then it will complain about that. And it leaves that code for sure as the backtrace of CPU0 hits user space later on.

4) the RT throttler hit?

Admittetly we dont know from which CPU and which task that comes but that's very simple to figure out. Debug patch below.

5) that the system makes progress afterwards?

6) ....

If my assumption about an interrupt storm turns out to be true, then it explain all of the above. I might be wrong as usual, but I still think its worth to have a look.

Thanks,

tglx
---

index ee15f5a0d1c1..d9e4153d405b 100644
@@ -895,7 +895,8 @@ static int sched_rt_runtime_exceeded(struct rt_rq *rt_rq)
 		 */
 		if (likely(rt_b->rt_runtime)) {
 			rt_rq->rt_throttled = 1;
-			printk_deferred_once("sched: RT throttling activated\n");
+			printk_deferred_once("sched: RT throttling activated cpu %d task %s %d\n",
+					     smp_processor_id(), current->comm, current->pid);
 		} else {
 			/*
 			 * In case we did anyway, make it go away,

No. Really. No.

There is no way in hell that a modern system ends up being that synchronized. Not to the point that the interrupt also happens at the *exact* same point.

Thomas, you're in denial. It's not just the exact same instruction in the timer interrupt handler ("timer interrupts and NMI's are in sync"), the call chain *past* the timer interrupt is the exact same thing too. The stack has the same contents. So not only must the two CPU's be perfectly in sync so that the NMI always triggers on exactly the same instruction, the CPU that takes the timer interrupt (in your schenario, over and over again) must be magically filling the stack with the exact same thing every time.

That CPU isn't making progress that just happens to be "synchronized".

Admit it, you've not seen a busy system that is *so* synchronized that you get timer interrupts and NMI's that hit on the same instruction over a sequence of minutes.

I'm claiming that the race happened *once*. And it then corrupted some data structure or similar sufficiently that CPU0 keeps looping.

Perhaps something keeps re-adding itself to the head of the timerqueue due to the race.

The watchdog doesn't trigger on CPU0, because this is the software watchdog, and interrupts are disabled on CPU0, and CPU0 isn't making any progress. Because it's looping in a fairly tight loop.

The watchdog triggers on CPU1 (over and over again) because CPU1 is waiting for the TLB shootdown to complete. And it doesn't, because interrupts are disabled on CPU0 that it's trying to shoot down the TLB on.

That theory at least fits the data. So CPU1 isn't doing anything odd at all.

In a way that "magic happens so that everything is so synchronized that you cross-syncornize two CPU's making real progress over many minutes". THAT sounds like just a fairy tale to me.

Your argument "it has a question mark in front of it" objection is bogus. We got an *interrupt* in the middle of the call chain. Of *course* the call chain is unreliable. It doesn't matter. What matters is that the stack under the interrupt DOES NOT CHANGE. It doesn't even matter if it's a real honest-to-god callchain or not, what matters is that the kernel stack under the interrupt is unchanged. No way does that happen if it's making progress at the same time.

At a guess, it's looping (for a long long time) on timerqueue_getnext() in hrtimer_interrupt(), and then returns. Never gets to the retry or the "interrupt took %llu" messages.

And we know what timer entry it is looping on: tick_sched_timer. Which does a HRTIMER_RESTART, so the re-enqueueing isn't exactly unlikely.

All it needs is that the re-enqueueing has gotten confused enough that it re-enqueues it on the same queue over and over again. Which would run tick_sched_timer over and over again. No? Until the re-enqueuing magically stops (and we do actually have a HPET counter overflow there. Just look at the RAX values:

RAX: 00000000fb9d303f
RAX: 000000002b67efe4

that 00000000fb9d303f is the last time we see that particular callchain. The next time we see hpet_read(), it's that 000000002b67efe4 thing.

So my "maybe it has something to do with HPET overflow" wasn't just a random throw-away comment. We actually have real data saying that the HPET *did* overflow, and it in fact happened somewhere around the time when the lockup went away.

Are they related? Maybe not. But dammit, there's a lot of "coincidences" here. Not just the "oh, it always takes the NMI on the exact same instruction".

.. something eventually clears the problem, maybe because of the HPET overflow. I dunno. I'm just saying that your arguments to ignore CPU0 are pretty damn weak.

So I think the CPU1 behavior is 100% consistent with CPU0 just having interrupts disabled.

So I think CPU1 is _trivial_ to explain if you accept that CPU0 is doing something weird.

Which is why I think your "look at CPU1" sounds so strange. I don't think CPU1 is all that interesting. I can *trivially* explain it with a single sentence, and did exactly that above.

Can you trivially explain CPU0? Without the "it's just a big coincidence that we take the NMI on the same instruction for several minutes, and the stack under the timer interrupt hasn't changed at all in that same time".

Linus

So tick_sched_timer() does

        ktime_t now = ktime_get();
        ...
        hrtimer_forward(timer, now, tick_period);
        return HRTIMER_RESTART;

and then __run_hrtimer does

        enqueue_hrtimer(timer, base);

which just adds the timer back on the tiemr heap.

So all you need to get an infinite loop (as far as I can see) is that hrtimer_forward() doesn't actually move the timer forward.

The most likely reason would seem to be this:

        delta = ktime_sub(now, hrtimer_get_expires(timer));

        if (delta.tv64 < 0)
                return 0;

and clearly it *should* return a positive number, since the timer has expired, so the expiry time _should_ be smaller than "now". So it should never trigger, and this bug is clearly impossible.

HOWEVER.

It turns out that while tick_sched_timer() does "ktime_get()" to get the current time, the actual timer machinery does *not* do that at all. The actual timer machinery does

        entry_time = now = hrtimer_update_base(cpu_base);

                base = cpu_base->clock_base + i;
                basenow = ktime_add(now, base->offset);

_once_ per hrtimer_clock_base. And then it iterates using that "basenow" thing, and compares it to the timer expiry.

So we have two different times. Now, let's think about what happens if those clocks aren't quote in sync.

We know (since __run_hrtimer was called) that

basenow.tv64 > hrtimer_get_softexpires_tv64(timer)

but here we have "basenow" - which is not that ktime_get(), and we have "hrtimer_get_softexpires_tv64()" (which is not hrtimer_get_expires() in general - we have all that "delta" range handling, but for the scheduling tick it *should* be the same).

So I can see at least one lockup:

- if "expires < basenow" hrtimer_interrupt() will run the timer
- if "now < expires" hrtimer_forward() will not do anything, and will
just reschedule the timer with the same expiration

iow, all you need for a re-arming of the same timer is:

now < expires < basenow

now, the two clocks (now and basenow) are not the same, but they do have the same *base*. So they are related, but even the base time was gotten under two different sequence locks, so even the base could have been updated in between the hrtimer_update_base() time and the ktime_get(). And even though they have the same base, they have different offsets: basenow does that "base->offset" thing (and ktime_get_update_offsets_now() does timekeeping_get_ns()

- now = ktime_get() does

                base = tk->tkr.base_mono;
                nsecs = timekeeping_get_ns(&tk->tkr);

- basenow = ktime_get_update_offsets_now() does

                base = tk->tkr.base_mono;
                nsecs = timekeeping_get_ns(&tk->tkr);
          .. and then ..
                ktime_add(.., base->offset);

and if I read the thing right, the ktime_add() should be a no-op, because base->offset should be 0 for the normal monotonic clock. Right?

So the two times (now and basenow) *should* be the same time, and the whole "now < expires < basenow" situation can never happen. Right?

Potentially wrong.

Because that's where the whole "different sequence locks" comes in. The one-time race could be something that updates the base in between the (one-time) ktime_get_update_offsets_now() and the (then as a result pseudo-infinitely repeating) ktime_get.

Hmm? If "base" ever goes backwards, or if "base" does *not* update atomically with the HPET timer overflows, I can see that happening. Of course, that would imply that ktime_get() is not monotonic. But we do know that we've had odd time issues on that machine.

I think you already had DaveJ check clock monotonicity. But that was with the TSC, wasn't it? I'm claiming maybe the HPET isn't monotonic, and there is some HPET clocksource issue with overflow in 32 bits.

(I think the HPET *should* be 64-bit, and just the comparators for interrupts may be 32-bit, but we use a "readl()" and only use the low 32-bits even if the upper 32 bits *might* be ok).

I keep harping on that HPET overflow, because we actually have the 6 "locked up" HPET traces, and then we have a seventh without that lockup, and there definitely was a overflow in 32 bits:

[torvalds@i7 linux]$ grep -3 read_hpet+0x16 ~/dj-1.txt | grep RAX
RAX: 0000000061fece8a RBX: 0000000000510792 RCX: 0000000000000000
RAX: 0000000079e588fc RBX: 0000000000511d6e RCX: 0000000000000000
RAX: 0000000091ca7f65 RBX: 0000000000513346 RCX: 0000000000000000
RAX: 00000000a9afbd0d RBX: 000000000051491e RCX: 0000000000000000
RAX: 00000000cbd1340c RBX: 000000000051684a RCX: 0000000000000000
RAX: 00000000fb9d303f RBX: 00000000005193fc RCX: 0000000000000000
RAX: 000000002b67efe4 RBX: 000000000051c224 RCX: 0000000000000004

and I have just gotten hung up on that small detail.

How/where is the HPET overflow case handled? I don't know the code enough.

(Also, maybe I shouldn't be so hung up on this *one* long trace from DaveJ. There's been a lot of crazy traces from that machine. We've had some time-handling questions about it before, but *most* of the traces have not been implicating the HPET like this one, so..)

Linus

Hmm, ok, I've re-acquainted myself with it. And I have to admit that I can't see anything wrong. The whole "update_wall_clock" and the shadow timekeeping state is confusing as hell, but seems fine. We'd have to avoid update_wall_clock for a *long* time for overflows to occur.

And the overflow in 32 bits isn't that special, since the only thing that really matters is the overflow of "cycle_now - tkr->cycle_last" within the mask.

So I'm not seeing anything even halfway suspicious.

Linus

One long shot is a bug in rcu_barrier() that I introduced in v3.18-rc1. This is a low-probability race that can cause rcu_barrier() and friends to return too soon, which can of course result in arbitrary misbehavior. Please see below for a fix which looks good thus far in reasonably intense rcutorture testing.

Might be what Dave and Sasha are seeing. Or not.

Thanx, Paul

------------------------------------------------------------------------

rcu: Fix rcu_barrier() race that could result in too-short wait

The rcu_barrier() no-callbacks check for no-CBs CPUs has race conditions. It checks a given CPU's lists of callbacks, and if all three no-CBs lists are empty, ignores that CPU. However, these three lists could potentially be empty even when callbacks are present if the check executed just as the callbacks were being moved from one list to another. It turns out that recent versions of rcutorture can spot this race.

This commit plugs this hole by consolidating the per-list counts of no-CBs callbacks into a single count, which is incremented before the corresponding callback is posted and after it is invoked. Then rcu_barrier() checks this single count to reliably determine whether the corresponding CPU has no-CBs callbacks.

index 7680fc275036..658b691dc32b 100644
@@ -3318,6 +3318,7 @@ static void _rcu_barrier(struct rcu_state *rsp)
 			} else {
 				_rcu_barrier_trace(rsp, "OnlineNoCB", cpu,
 						   rsp->n_barrier_done);
+				smp_mb__before_atomic();
 				atomic_inc(&rsp->barrier_cpu_count);
 				__call_rcu(&rdp->barrier_head,
 					   rcu_barrier_callback, rsp, cpu, 0);

index 8e7b1843896e..cb5908672f11 100644
@@ -340,14 +340,10 @@ struct rcu_data {
 #ifdef CONFIG_RCU_NOCB_CPU
 	struct rcu_head *nocb_head;	/* CBs waiting for kthread. */
 	struct rcu_head **nocb_tail;
-	atomic_long_t nocb_q_count;	/* # CBs waiting for kthread */
-	atomic_long_t nocb_q_count_lazy; /*  (approximate). */
+	atomic_long_t nocb_q_count;	/* # CBs waiting for nocb */
+	atomic_long_t nocb_q_count_lazy; /*  invocation (all stages). */
 	struct rcu_head *nocb_follower_head; /* CBs ready to invoke. */
 	struct rcu_head **nocb_follower_tail;
-	atomic_long_t nocb_follower_count; /* # CBs ready to invoke. */
-	atomic_long_t nocb_follower_count_lazy; /*  (approximate). */
-	int nocb_p_count;		/* # CBs being invoked by kthread */
-	int nocb_p_count_lazy;		/*  (approximate). */
 	wait_queue_head_t nocb_wq;	/* For nocb kthreads to sleep on. */
 	struct task_struct *nocb_kthread;
 	int nocb_defer_wakeup;		/* Defer wakeup of nocb_kthread. */

@@ -356,8 +352,6 @@ struct rcu_data {
 	struct rcu_head *nocb_gp_head ____cacheline_internodealigned_in_smp;
 					/* CBs waiting for GP. */
 	struct rcu_head **nocb_gp_tail;
-	long nocb_gp_count;
-	long nocb_gp_count_lazy;
 	bool nocb_leader_sleep;		/* Is the nocb leader thread asleep? */
 	struct rcu_data *nocb_next_follower;
 					/* Next follower in wakeup chain. */

@@ -622,24 +616,15 @@ static void rcu_dynticks_task_exit(void);
 #endif /* #ifndef RCU_TREE_NONCORE */
 
 #ifdef CONFIG_RCU_TRACE
-#ifdef CONFIG_RCU_NOCB_CPU
-/* Sum up queue lengths for tracing. */
+/* Read out queue lengths for tracing. */
 static inline void rcu_nocb_q_lengths(struct rcu_data *rdp, long *ql, long *qll)
 {
-	*ql = atomic_long_read(&rdp->nocb_q_count) +
-	      rdp->nocb_p_count +
-	      atomic_long_read(&rdp->nocb_follower_count) +
-	      rdp->nocb_p_count + rdp->nocb_gp_count;
-	*qll = atomic_long_read(&rdp->nocb_q_count_lazy) +
-	       rdp->nocb_p_count_lazy +
-	       atomic_long_read(&rdp->nocb_follower_count_lazy) +
-	       rdp->nocb_p_count_lazy + rdp->nocb_gp_count_lazy;
-}
+#ifdef CONFIG_RCU_NOCB_CPU
+	*ql = atomic_long_read(&rdp->nocb_q_count);
+	*qll = atomic_long_read(&rdp->nocb_q_count_lazy);
 #else /* #ifdef CONFIG_RCU_NOCB_CPU */
-static inline void rcu_nocb_q_lengths(struct rcu_data *rdp, long *ql, long *qll)
-{
 	*ql = 0;
 	*qll = 0;
-}
 #endif /* #else #ifdef CONFIG_RCU_NOCB_CPU */
+}
 #endif /* #ifdef CONFIG_RCU_TRACE */

.. of course, this reminds me of the "clocksource TSC unstable" issue.

Then *simple* solution may actually be that the HPET itself is buggered. That would explain both the "clocksource TSC unstable" messages _and_ the "time went backwards, so now we're re-arming the scheduler tick 'forever' until time has gone forwards again".

And googling for this actually shows other people seeing similar issues, including hangs after switching to another clocksource. See for example

http://stackoverflow.com/questions/13796944/system-hang-with-possible-relevance-to-clocksource-tsc-unstable

which switches to acpi_pm (not HPET) and then hangs afterwards.

Of course, it may be the switching itself that causes some issue.

Btw, there's another reason to think that it's the HPET, I just realized.

DaveJ posted all his odd TSC unstable things, and the delta was pretty damn random. But it did have a range: it was in the 1-251 second range.

With a 14.318MHz clock (which is, I think, the normal HPET frequency), a 32-bit overflow happens in about 300 seconds.

So the range of 1-251 seconds is not entirely random. It's all in that "32-bit HPET range".

In contrast, wrt the TSC frequency, that kind of range makes no sense at all.

Linus

DaveJ, I assume it's too late now, and you don't effectively have any access to the machine any more, but "hpet=disable" or "nohpet" on the command line might be worth trying if you ever see that piece of hardware again.

And for posterity, do you have a dmidecode with motherboard/BIOS information for the problematic machine? And your configuration?

And finally, and stupidly, is there any chance that you have anything accessing /dev/hpet?

Linus

I can give it a try tomorrow. I'm probably saying goodbye to that machine on Tuesday, so we'll have 24hrs of testing at least.

I can grab that in the morning too.

Not knowingly at least, but who the hell knows what systemd has its fingers in these days.

Dave

Actually, it looks like /dev/hpet doesn't allow write access.

I can do the mmap(/dev/mem) thing and access the HPET by hand, and when I write zero to it I immediately get something like this:

Clocksource tsc unstable (delta = -284317725450 ns) Switched to clocksource hpet

just to confirm that yes, a jump in the HPET counter would indeed give those kinds of symptoms:blaming the TSC with a negative delta in the 0-300s range, even though it's the HPET that is broken.

And if the HPET then occasionally jumps around afterwards, it would show up as ktime_get() occasionally going backwards, which in turn would - as far as I can tell - result in exactly that pseudo-infirnite loop with timers.

Anyway, any wild kernel pointer access *could* happen to just hit the HPET and write to the main counter value, although I'd personally be more inclined to blame BIOS/SMM kind of code playing tricks with time.. We do have a few places where we explicitly write the value on purpose, but they are in the HPET init code, and in the clocksource resume code, so they should not be involved.

Thomas - have you had reports of HPET breakage in RT circles, the same way BIOSes have been tinkering with TSC?

Also, would it perhaps be a good idea to make "ktime_get()" save the last time in a percpu variable, and warn if time ever goes backwards on a particular CPU? A percpu thing should be pretty cheap, even if we write to it every time somebody asks for time..

Linus

Ok, so I tried that too.

It's actually a pretty easy experiment to do: just mmap(/dev/mem) at the HPET offset (the kernel prints it out at boot, it should normally be at 0xfed00000). And then just write a zero to offset 0xf0, which is the main counter.

The first time, you get the "Clocksource tsc unstable".

The second time (or third, or fourth - it might not take immediately) you get a lockup or similar. Bad things happen.

This is *not* to say that this is the bug you're hitting. But it does show that

(a) a flaky HPET can do some seriously bad stuff
(b) the kernel is very fragile wrt time going backwards.

and maybe we can use this test program to at least try to alleviate problem (b).

Trivial HPET mess-up program attached.

Linus

#include <sys/types.h>
#include <sys/stat.h>
#include <fcntl.h>
#include <sys/mman.h>
#include <stdio.h>

int main(int argc, char **argv)

{
	int fd = open("/dev/mem", O_RDWR);
	void *base;

	if (fd < 0) {
		fputs("Unable to open /dev/mem\n", stderr);
		return -1;
	}
	base = mmap(NULL, 4096 ,PROT_READ | PROT_WRITE, MAP_SHARED, fd, 0xfed00000);
	if ((long)base == -1) {
		fputs("Unable to mmap HPET\n", stderr);
		return -1;
	}
	*(unsigned long *) (base+0xf0) = 0;
	return 0;
}

I've only tested it twice now, but the first time I got a weird lockup-like thing (things *kind* of worked, but I could imagine that one CPU was stuck with a lock held, because things eventually ground to a screeching halt.

The second time I got

  INFO: rcu_sched self-detected stall on CPU { 5}  (t=84533 jiffies

g=11971 c=11970 q=17)

and then

   INFO: rcu_sched detected stalls on CPUs/tasks: { 1 2 3 4 5 6 7}

(detected by 0, t=291309 jiffies, g=12031, c=12030, q=57)

with backtraces that made no sense (because obviously no actual stall had taken place), and were the CPU's mostly being idle.

I could easily see it resulting in your softlockup scenario too.

Linus

So something trinity does when it doesn't have a better idea of something to pass a syscall is to generate a random number.

A wild hypothesis could be that we're in one of these situations, and we randomly generated 0xfed000f0 and passed that as a value to a syscall, and the kernel wrote 0 to that address.

What syscall could do that, and not just fail a access_ok() or similar is a mystery though.

Dave

Yep, if time gets messed up too much, RCU can incorrectly decide that 21 seconds have elapsed since the grace period started, and can even decide this pretty much immediately after the grace period starts.

Thanx, Paul

Ok, so after several false starts (ktime_get() is really really fragile - called in scheduler things, and doing magic things at bootup), here is something that seems to alleviate the problem for me.

I still get a lot of RCU messages like "self-detected stall" etc, but that's to be expected. When the clock does odd things, crap *will* happen.

But what this does is:

(a) make the error more visible as a clock error rather than various
random downstream users

IOW, it prints things out when it looks like we're getting odd
clock read errors (arbitrary cut-off: we expect clock read-outs to be withing 1/8th of the range of the expected clock value)

(b) try to alleviate the horrible things that happen when the clock
error is big

The patch tries to "correct" for the huge time jump by basically
undoing it. We'll still see time jumps (there really is no way to avoid it), but we limit the range of them.

With the attached patch, my machine seems to survive me writing to the HPET master counter register. It spews warnings, and it is noisy about the odd clock reads:

...
Clocksource hpet had cycles off by 642817751
Cutting it too close for hpet in in update_wall_time (offset = 4034102337)
INFO: rcu_sched self-detected stall on CPU { 0} (t=281743 jiffies
g=4722 c=4721 q=14)

    ...

and there may still be situations where it does horrible horrible things due to the (smaller) time leaps, but it does seem a lot more robust.

NOTE! There's an (intentional) difference in how we handle the time leaps at time read time vs write (wall-clock update).

At time read time, we just refuse to believe the big delta, and we set the "cycle_error" value so that future time reads will be relative to the error we just got. We also don't print anything out, because we're possibly deep in the scheduler or in tracing, and we do not want to spam the console about our fixup.

At time *write* time, we first report about any read-time errors, and then we report (but believe in) overlarge clocksource delta errors as we update the time.

This seems to be the best way to limit the damage.

Also note that the patch is entirely clock-agnostic. It's just that I can trivially screw up my HPET, I didn't look at other clocks.

One note: my current limit of clocksource delta errors is based on the range of the clock (1/8th of the range). I actually think that's bogus, and it should instead be based on the expected frequency of the clock (ie "we are guaranteed to update the wall clock at least once every second, so if the clock source delta read is larger than one second, we've done something wrong"). So this patch is meant very much as an RFC, rather than anything else. It's pretty hacky. But it does actually make a huge difference for me wrt the "mess up HPET time on purpose". That used to crash my machine pretty hard, and pretty reliably. With this patch, I've done it ten+ times, and while it spews a lot of garbage, the machine stays up and _works_.

Making the sanity check tighter (ie the "one second" band rather than "1/8th of the clock range") would probably just improve it further.

Thomas, what do you think? Hate it? Any better ideas?

And again: this is not trying to make the kernel clock not jump. There is no way I can come up with even in theory to try to really *fix* a fundamentally broken clock.

So this is not meant to be a real "fix" for anything, but is meant to make sure that if the clock is unreliable, we pinpoint the clock itself, and it mitigates the absolutely horrendously bad behavior we currently with bad clocks. So think of this as debug and band-aid rather than "this makes clocks magically reliable".

.. and we might still lock up under some circumstances. But at least from my limited testing, it is infinitely much better, even if it might not be perfect. Also note that my "testing" has been writing zero to the HPET lock (so the HPET clock difference tends to be pretty specific), while my next step is to see what happens when I write random values (and a lot of them).

Since I expect that to cause more problems, I thought I'd send this RFC out before I start killing my machine again ;)

Linus

 include/linux/timekeeper_internal.h |  1 +
 kernel/time/timekeeping.c           | 25 ++++++++++++++++++++++++-
 2 files changed, 25 insertions(+), 1 deletion(-)

index 05af9a334893..0fcb60d77079 100644
@@ -32,6 +32,7 @@ struct tk_read_base {
 	cycle_t			(*read)(struct clocksource *cs);
 	cycle_t			mask;
 	cycle_t			cycle_last;
+	cycle_t			cycle_error;
 	u32			mult;
 	u32			shift;
 	u64			xtime_nsec;

index 6a931852082f..1c842ddd567f 100644
@@ -140,6 +140,7 @@ static void tk_setup_internals(struct timekeeper *tk, struct clocksource *clock)
 	tk->tkr.read = clock->read;
 	tk->tkr.mask = clock->mask;
 	tk->tkr.cycle_last = tk->tkr.read(clock);
+	tk->tkr.cycle_error = 0;
 
 	/* Do the ns -> cycle conversion first, using original mult */
 	tmp = NTP_INTERVAL_LENGTH;

@@ -197,11 +198,17 @@ static inline s64 timekeeping_get_ns(struct tk_read_base *tkr)
 	s64 nsec;
 
 	/* read clocksource: */
-	cycle_now = tkr->read(tkr->clock);
+	cycle_now = tkr->read(tkr->clock) + tkr->cycle_error;
 
 	/* calculate the delta since the last update_wall_time: */
 	delta = clocksource_delta(cycle_now, tkr->cycle_last, tkr->mask);
 
+	/* Hmm? This is really not good, we're too close to overflowing */
+	if (unlikely(delta > (tkr->mask >> 3))) {
+		tkr->cycle_error = delta;
+		delta = 0;
+	}
+
 	nsec = delta * tkr->mult + tkr->xtime_nsec;
 	nsec >>= tkr->shift;
 

@@ -465,6 +472,16 @@ static void timekeeping_update(struct timekeeper *tk, unsigned int action)
 	update_fast_timekeeper(tk);
 }
 
+static void check_cycle_error(struct tk_read_base *tkr)
+{
+	cycle_t error = tkr->cycle_error;
+
+	if (unlikely(error)) {
+		tkr->cycle_error = 0;
+		pr_err("Clocksource %s had cycles off by %llu\n", tkr->clock->name, error);
+	}
+}
+
 /**
  * timekeeping_forward_now - update clock to the current time
  *

@@ -481,6 +498,7 @@ static void timekeeping_forward_now(struct timekeeper *tk)
 	cycle_now = tk->tkr.read(clock);
 	delta = clocksource_delta(cycle_now, tk->tkr.cycle_last, tk->tkr.mask);
 	tk->tkr.cycle_last = cycle_now;
+	check_cycle_error(&tk->tkr);
 
 	tk->tkr.xtime_nsec += delta * tk->tkr.mult;
 

@@ -1237,6 +1255,7 @@ static void timekeeping_resume(void)
 
 	/* Re-base the last cycle value */
 	tk->tkr.cycle_last = cycle_now;
+	tk->tkr.cycle_error = 0;
 	tk->ntp_error = 0;
 	timekeeping_suspended = 0;
 	timekeeping_update(tk, TK_MIRROR | TK_CLOCK_WAS_SET);

@@ -1591,11 +1610,15 @@ void update_wall_time(void)
 	if (unlikely(timekeeping_suspended))
 		goto out;
 
+	check_cycle_error(&real_tk->tkr);
+
 #ifdef CONFIG_ARCH_USES_GETTIMEOFFSET
 	offset = real_tk->cycle_interval;
 #else
 	offset = clocksource_delta(tk->tkr.read(tk->tkr.clock),
 				   tk->tkr.cycle_last, tk->tkr.mask);
+	if (unlikely(offset > (tk->tkr.mask >> 3)))
+		pr_err("Cutting it too close for %s in in update_wall_time (offset = %llu)\n", tk->tkr.clock->name, offset);
 #endif
 
 	/* Check if there's really nothing to do */

Ok, not horrible. Although I'd suggest not testing in a terminal window while running X. The time jumping will confuse X input timing and the screensaver, to the point that the machine may not be dead, but it isn't exactly usable. Do it in a virtual console.

Again, making the limit tighter (one second?) and perhaps not trusting insane values too much at walltime clock update time either, might make it all work smoother still.

I did manage to confuse systemd with all the garbage the kernel spewed, with a lot of stuff like:

systemd-journald[779]: Failed to write entry (9 items, 276 bytes),
ignoring: Invalid argument

showing up in the logs, but I'm writing this without having had to reboot the machine.

Linus

I tried the nohpet thing for a few hours this morning and didn't see anything weird, but it may have been that I just didn't run long enough. When I saw your patch, I gave that a shot instead, with hpet enabled again. Just got back to find lots of messages in dmesg, but none of the usual NMI/lockup messages.

[ 2256.430694] Clocksource tsc unstable (delta = -142018897190 ns)
[ 2256.437433] Switched to clocksource hpet
[ 2279.788605] Clocksource hpet had cycles off by 4294946559
[ 2280.191272] Clocksource hpet had cycles off by 4294905111
[ 2282.605990] Clocksource hpet had cycles off by 4294960721
[ 2284.485410] Clocksource hpet had cycles off by 4294953427
[ 2288.954844] Clocksource hpet had cycles off by 4294924880
[ 2305.202931] Clocksource hpet had cycles off by 4294960429
[ 2315.527247] Clocksource hpet had cycles off by 4294956296
[ 2318.954066] Clocksource hpet had cycles off by 4293673652
[ 2332.370923] Clocksource hpet had cycles off by 4294907221
[ 2332.739861] Clocksource hpet had cycles off by 4294919496
[ 2345.459694] Clocksource hpet had cycles off by 4294959592
[ 2346.159780] Clocksource hpet had cycles off by 4294952613
[ 2348.132071] Clocksource hpet had cycles off by 4294903415
[ 2348.207593] Clocksource hpet had cycles off by 4294966900
[ 2351.699779] Clocksource hpet had cycles off by 4294906755
[ 2354.125982] Clocksource hpet had cycles off by 4294941028
[ 2365.249438] Clocksource hpet had cycles off by 4294942458
[ 2370.247560] Clocksource hpet had cycles off by 4294927938
[ 2372.554642] Clocksource hpet had cycles off by 4294950723
[ 2377.361721] Clocksource hpet had cycles off by 4294952569
[ 2384.747820] Clocksource hpet had cycles off by 4294947263
[ 2389.133886] Clocksource hpet had cycles off by 4294967233
[ 2392.423458] Clocksource hpet had cycles off by 4294946214
[ 2397.648955] Clocksource hpet had cycles off by 4294967205
[ 2405.228015] Clocksource hpet had cycles off by 4294917938
[ 2429.571163] Clocksource hpet had cycles off by 4294957112
[ 2434.214788] Clocksource hpet had cycles off by 4294866662
[ 2438.686705] Clocksource hpet had cycles off by 4294945380
[ 2440.280478] Clocksource hpet had cycles off by 4294878090
[ 2458.370164] Clocksource hpet had cycles off by 4294875577
[ 2496.916971] Clocksource hpet had cycles off by 4294887574
[ 2516.314875] Clocksource hpet had cycles off by 4294899744
[ 2519.857221] Clocksource hpet had cycles off by 4294836752
[ 2522.696576] Clocksource hpet had cycles off by 4294965711
[ 2527.599967] Clocksource hpet had cycles off by 4294876467
[ 2528.573678] Clocksource hpet had cycles off by 4294815154
[ 2537.325296] Clocksource hpet had cycles off by 4294862624
[ 2542.296016] Clocksource hpet had cycles off by 4294954228
[ 2558.634123] Clocksource hpet had cycles off by 4294845883
[ 2560.804973] Clocksource hpet had cycles off by 4294958781
[ 2579.057030] Clocksource hpet had cycles off by 4294921012
[ 2588.139716] Clocksource hpet had cycles off by 4294950381
[ 2594.076877] Clocksource hpet had cycles off by 4294941777
[ 2597.645800] Clocksource hpet had cycles off by 4294927609
[ 2605.032338] Clocksource hpet had cycles off by 4294915823
[ 2605.239672] Clocksource hpet had cycles off by 4294952275
[ 2605.294230] Clocksource hpet had cycles off by 4294886603
[ 2609.801532] Clocksource hpet had cycles off by 4294887976
[ 2615.003674] Clocksource hpet had cycles off by 4294957202
[ 2641.039536] Clocksource hpet had cycles off by 4294943689
[ 2644.554947] Clocksource hpet had cycles off by 4294837076
[ 2648.576203] Clocksource hpet had cycles off by 4294928887
[ 2648.627249] Clocksource hpet had cycles off by 4294913656
[ 2680.465314] Clocksource hpet had cycles off by 4294963565
[ 2705.231925] Clocksource hpet had cycles off by 4294949762
[ 2708.181981] Clocksource hpet had cycles off by 4294924526
[ 2713.622343] Clocksource hpet had cycles off by 4294874217
[ 2714.725619] Clocksource hpet had cycles off by 4294961341
[ 2722.302868] Clocksource hpet had cycles off by 4294937888
[ 2723.351842] Clocksource hpet had cycles off by 4294943821
[ 2724.230634] Clocksource hpet had cycles off by 4294953908
[ 2734.508428] Clocksource hpet had cycles off by 4294900255
[ 2743.480843] Clocksource hpet had cycles off by 4294934465
[ 2748.638267] Clocksource hpet had cycles off by 4294928479
[ 2750.374907] Clocksource hpet had cycles off by 4294962242
[ 2752.883492] Clocksource hpet had cycles off by 4294961729
[ 2762.358287] Clocksource hpet had cycles off by 4294957673
[ 2777.020231] Clocksource hpet had cycles off by 4294951532
[ 2789.811124] Clocksource hpet had cycles off by 4294832640
[ 2808.599221] perf interrupt took too long (2506 > 2500), lowering kernel.perf_event_max_sample_rate to 50000
[ 2812.309248] Clocksource hpet had cycles off by 4294959285
[ 2820.167264] Clocksource hpet had cycles off by 4294922522
[ 2825.981201] Clocksource hpet had cycles off by 4294961107
[ 2849.266035] Clocksource hpet had cycles off by 4294322241
[ 2862.090994] Clocksource hpet had cycles off by 4294807837
[ 2864.602231] Clocksource hpet had cycles off by 4292691328
[ 2875.567269] Clocksource hpet had cycles off by 4294892749
[ 2876.792253] Clocksource hpet had cycles off by 4294954356
[ 2877.242823] Clocksource hpet had cycles off by 4294942513
[ 2883.445407] Clocksource hpet had cycles off by 4294854046
[ 2884.018795] Clocksource hpet had cycles off by 4294943942
[ 2924.508029] Clocksource hpet had cycles off by 4294913383
[ 2928.152682] Clocksource hpet had cycles off by 4294951984
[ 2942.827401] Clocksource hpet had cycles off by 4294905917
[ 2979.433869] Clocksource hpet had cycles off by 4294939435
[ 3003.908148] Clocksource hpet had cycles off by 4294961616
[ 3038.850267] Clocksource hpet had cycles off by 4294927946
[ 3044.954639] Clocksource hpet had cycles off by 4294958095
[ 3061.620024] Clocksource hpet had cycles off by 4294885942
[ 3073.112084] Clocksource hpet had cycles off by 4294904313
[ 3102.306426] Clocksource hpet had cycles off by 4294886586
[ 3132.345432] Clocksource hpet had cycles off by 4294938217
[ 3138.942577] Clocksource hpet had cycles off by 4294924394
[ 3142.071929] Clocksource hpet had cycles off by 4294907682
[ 3146.492397] Clocksource hpet had cycles off by 4294864373
[ 3166.314671] Clocksource hpet had cycles off by 4294953858
[ 3178.918199] Clocksource hpet had cycles off by 4294942016
[ 3188.422027] Clocksource hpet had cycles off by 4294951735
[ 3194.288347] Clocksource hpet had cycles off by 4294955749
[ 3209.949342] Clocksource hpet had cycles off by 4294954855
[ 3210.908565] Clocksource hpet had cycles off by 4294958025
[ 3215.309835] Clocksource hpet had cycles off by 4294903310
[ 3215.478186] Clocksource hpet had cycles off by 4294925603
[ 3220.315692] Clocksource hpet had cycles off by 4294921130
[ 3240.091173] Clocksource hpet had cycles off by 4294965151
[ 3241.310332] Clocksource hpet had cycles off by 4294920337
[ 3256.946306] Clocksource hpet had cycles off by 4294895161
[ 3274.502015] Clocksource hpet had cycles off by 4294954311
[ 3292.591837] Clocksource hpet had cycles off by 4294950141
[ 3303.335861] Clocksource hpet had cycles off by 4294803418
[ 3326.010088] Clocksource hpet had cycles off by 4294841425
[ 3326.811161] Clocksource hpet had cycles off by 4294962464
[ 3330.472170] Clocksource hpet had cycles off by 4294917788
[ 3340.393483] Clocksource hpet had cycles off by 4294816705
[ 3344.508292] Clocksource hpet had cycles off by 4294856944
[ 3353.028263] Clocksource hpet had cycles off by 4294929946
[ 3358.636907] Clocksource hpet had cycles off by 4294902855
[ 3393.123323] Clocksource hpet had cycles off by 4294954661
[ 3395.373158] Clocksource hpet had cycles off by 4294938408
[ 3396.705795] Clocksource hpet had cycles off by 4294889623
[ 3398.205662] Clocksource hpet had cycles off by 4294879106
[ 3401.179862] Clocksource hpet had cycles off by 4294937424
[ 3411.096003] Clocksource hpet had cycles off by 4294910612
[ 3435.494311] Clocksource hpet had cycles off by 4294875772
[ 3444.877243] Clocksource hpet had cycles off by 4294899367
[ 3474.106134] Clocksource hpet had cycles off by 4294959423
[ 3474.166008] Clocksource hpet had cycles off by 4294960630
[ 3494.407860] Clocksource hpet had cycles off by 4294909541
[ 3500.723084] Clocksource hpet had cycles off by 4294925671
[ 3502.921757] Clocksource hpet had cycles off by 4294926449
[ 3508.518955] Clocksource hpet had cycles off by 4294920226
[ 3533.172055] Clocksource hpet had cycles off by 4294957897
[ 3533.185116] Clocksource hpet had cycles off by 4294913906
[ 3540.982091] Clocksource hpet had cycles off by 4294892669
[ 3543.816807] Clocksource hpet had cycles off by 4294944846
[ 3544.456059] Clocksource hpet had cycles off by 4294950209
[ 3549.528972] Clocksource hpet had cycles off by 4294866480
[ 3550.765097] Clocksource hpet had cycles off by 4294911727
[ 3552.171078] Clocksource hpet had cycles off by 4294957875
[ 3552.331984] Clocksource hpet had cycles off by 4294800210
[ 3561.750983] Clocksource hpet had cycles off by 4294879617
[ 3564.864088] Clocksource hpet had cycles off by 4294952537
[ 3566.032836] Clocksource hpet had cycles off by 4294960751
[ 3584.384888] Clocksource hpet had cycles off by 4294922502
[ 3585.272470] Clocksource hpet had cycles off by 4294949766
[ 3590.822550] Clocksource hpet had cycles off by 4294902676
[ 3593.347261] Clocksource hpet had cycles off by 4294957358
[ 3603.374532] Clocksource hpet had cycles off by 4294913488
[ 3627.928013] Clocksource hpet had cycles off by 4294946425
[ 3629.977816] Clocksource hpet had cycles off by 4294932328
[ 3631.198377] Clocksource hpet had cycles off by 4294914213
[ 3631.238396] Clocksource hpet had cycles off by 4294913701
[ 3631.333341] Clocksource hpet had cycles off by 4294841996
[ 3631.626025] Clocksource hpet had cycles off by 4294944292
[ 3631.745065] Clocksource hpet had cycles off by 4294957078
[ 3632.092954] Clocksource hpet had cycles off by 4294841257
[ 3632.454357] Clocksource hpet had cycles off by 4294961345
[ 3634.493806] Clocksource hpet had cycles off by 4294952357
[ 3635.153726] Clocksource hpet had cycles off by 4294948027
[ 3652.272623] Clocksource hpet had cycles off by 4294965136
[ 3656.902557] Clocksource hpet had cycles off by 4294927721
[ 3662.138415] Clocksource hpet had cycles off by 4294943626
[ 3664.735885] Clocksource hpet had cycles off by 4294958345
[ 3667.755405] Clocksource hpet had cycles off by 4294940238
[ 3685.903347] Clocksource hpet had cycles off by 4294962480
[ 3704.449524] Clocksource hpet had cycles off by 4294863510
[ 3728.823421] Clocksource hpet had cycles off by 4294892160
[ 3749.284831] Clocksource hpet had cycles off by 4294845549
[ 3799.003642] Clocksource hpet had cycles off by 4294880141
[ 3800.812777] Clocksource hpet had cycles off by 4294877511
[ 3806.316479] Clocksource hpet had cycles off by 4294922331
[ 3818.379672] Clocksource hpet had cycles off by 4294919579
[ 3824.536343] Clocksource hpet had cycles off by 4294916256
[ 3912.043508] Clocksource hpet had cycles off by 4294947596
[ 3914.773341] Clocksource hpet had cycles off by 4294927332
[ 3915.092603] Clocksource hpet had cycles off by 4294935220
[ 3918.711418] Clocksource hpet had cycles off by 4294922241
[ 3935.700688] Clocksource hpet had cycles off by 4294935334
[ 3944.982394] trinity-c119 (26679) used greatest stack depth: 8608 bytes left
[ 3945.144701] Clocksource hpet had cycles off by 4294942818
[ 3946.224074] Clocksource hpet had cycles off by 4294942933
[ 3952.200779] Clocksource hpet had cycles off by 4294940591
[ 3955.858738] Clocksource hpet had cycles off by 4294939648
[ 3958.188509] Clocksource hpet had cycles off by 4294923538
[ 3958.658586] Clocksource hpet had cycles off by 4294918578
[ 3975.317160] Clocksource hpet had cycles off by 4294944423
[ 3983.803077] Clocksource hpet had cycles off by 4294932553
[ 3985.311172] Clocksource hpet had cycles off by 4294947521
[ 3985.913043] Clocksource hpet had cycles off by 4294915749
[ 3998.665901] Clocksource hpet had cycles off by 4294912421
[ 4004.910893] Clocksource hpet had cycles off by 4294932330
[ 4014.406515] Clocksource hpet had cycles off by 4294916459
[ 4015.213388] Clocksource hpet had cycles off by 4294954637
[ 4024.019290] Clocksource hpet had cycles off by 4294940364
[ 4024.667464] Clocksource hpet had cycles off by 4294961248
[ 4024.937651] Clocksource hpet had cycles off by 4294956335
[ 4029.585715] Clocksource hpet had cycles off by 4294945561
[ 4030.797962] Clocksource hpet had cycles off by 4294903378
[ 4051.989581] Clocksource hpet had cycles off by 4294847969
[ 4070.615040] Clocksource hpet had cycles off by 4294902056
[ 4073.994411] Clocksource hpet had cycles off by 4294883107
[ 4080.916317] Clocksource hpet had cycles off by 4294941652
[ 4086.311462] Clocksource hpet had cycles off by 4294966537
[ 4090.010466] Clocksource hpet had cycles off by 4294950146
[ 4096.838086] Clocksource hpet had cycles off by 4294927769
[ 4104.491718] Clocksource hpet had cycles off by 4294955539
[ 4107.629077] Clocksource hpet had cycles off by 4294967271
[ 4125.898702] Clocksource hpet had cycles off by 4294964631
[ 4132.125374] Clocksource hpet had cycles off by 4294960839
[ 4142.642241] Clocksource hpet had cycles off by 4294918707
[ 4148.550288] Clocksource hpet had cycles off by 4294897635
[ 4148.745473] Clocksource hpet had cycles off by 4294965015
[ 4151.090145] Clocksource hpet had cycles off by 4294878713
[ 4152.214313] Clocksource hpet had cycles off by 4294952880
[ 4156.038261] Clocksource hpet had cycles off by 4294864713
[ 4162.478929] Clocksource hpet had cycles off by 4294945082
[ 4176.830542] Clocksource hpet had cycles off by 4294946310
[ 4195.020466] Clocksource hpet had cycles off by 4294796816
[ 4202.680429] Clocksource hpet had cycles off by 4294877002
[ 4249.878052] Clocksource hpet had cycles off by 4294949958
[ 4252.020356] Clocksource hpet had cycles off by 4294899168
[ 4252.637177] Clocksource hpet had cycles off by 4294796450
[ 4284.053708] Clocksource hpet had cycles off by 4294872739
[ 4294.238642] Clocksource hpet had cycles off by 4294860546
[ 4301.431434] Clocksource hpet had cycles off by 4294904168
[ 4307.412321] Clocksource hpet had cycles off by 4294841970
[ 4312.143379] Clocksource hpet had cycles off by 4294930826
[ 4314.093635] Clocksource hpet had cycles off by 4294910975
[ 4326.764818] Clocksource hpet had cycles off by 4294932296
[ 4329.571886] Clocksource hpet had cycles off by 4294950989
[ 4330.222706] Clocksource hpet had cycles off by 4294933891
[ 4347.066665] Clocksource hpet had cycles off by 4294880937
[ 4374.504888] Clocksource hpet had cycles off by 4294965440
[ 4382.493267] Clocksource hpet had cycles off by 4294922671
[ 4389.818116] Clocksource hpet had cycles off by 4294935624
[ 4393.376766] Clocksource hpet had cycles off by 4294925525
[ 4399.072216] Clocksource hpet had cycles off by 4294943563
[ 4419.290063] Clocksource hpet had cycles off by 4294950072
[ 4450.537859] Clocksource hpet had cycles off by 4294865975
[ 4464.675533] Clocksource hpet had cycles off by 4294925511
[ 4507.840126] Clocksource hpet had cycles off by 4294931748
[ 4508.161862] Clocksource hpet had cycles off by 4294915748
[ 4512.498940] Clocksource hpet had cycles off by 4294910106
[ 4514.624517] Clocksource hpet had cycles off by 4294955930
[ 4520.082370] Clocksource hpet had cycles off by 4294941408
[ 4531.884141] Clocksource hpet had cycles off by 4294961494
[ 4545.935603] Clocksource hpet had cycles off by 4294967229
[ 4556.241469] Clocksource hpet had cycles off by 4294941038
[ 4569.914804] Clocksource hpet had cycles off by 4294923318
[ 4570.422413] Clocksource hpet had cycles off by 4294953359
[ 4570.602296] Clocksource hpet had cycles off by 4294810379
[ 4570.794821] Clocksource hpet had cycles off by 4294915889
[ 4570.961255] Clocksource hpet had cycles off by 4294884105
[ 4575.453845] Clocksource hpet had cycles off by 4294891136
[ 4576.261732] Clocksource hpet had cycles off by 4294914711
[ 4605.592394] Clocksource hpet had cycles off by 4294948696
[ 4612.348715] Clocksource hpet had cycles off by 4294945417
[ 4634.628273] Clocksource hpet had cycles off by 4294910320
[ 4649.729320] Clocksource hpet had cycles off by 4294913504
[ 4661.279664] Clocksource hpet had cycles off by 4294956035
[ 4674.144390] Clocksource hpet had cycles off by 4294924970
[ 4712.119906] Clocksource hpet had cycles off by 4294960987
[ 4718.898730] Clocksource hpet had cycles off by 4294921730
[ 4751.991138] Clocksource hpet had cycles off by 4294899738
[ 4773.210994] Clocksource hpet had cycles off by 4294869476
[ 4789.097013] Clocksource hpet had cycles off by 4294938181
[ 4794.215907] Clocksource hpet had cycles off by 4294911648
[ 4808.794228] Clocksource hpet had cycles off by 4294958260
[ 4822.398742] Clocksource hpet had cycles off by 4294780976
[ 4822.596511] Clocksource hpet had cycles off by 4294954567
[ 4822.727585] Clocksource hpet had cycles off by 4294938077
[ 4822.817637] Clocksource hpet had cycles off by 4294936644
[ 4826.665756] Clocksource hpet had cycles off by 4294931735
[ 4838.959274] Clocksource hpet had cycles off by 4294779568
[ 4840.277796] Clocksource hpet had cycles off by 4294932970
[ 4845.753143] Clocksource hpet had cycles off by 4294954120
[ 4846.282983] Clocksource hpet had cycles off by 4294952329
[ 4864.693100] Clocksource hpet had cycles off by 4294941337
[ 4864.922970] Clocksource hpet had cycles off by 4294941269
[ 4867.012004] Clocksource hpet had cycles off by 4294937786
[ 4869.792338] Clocksource hpet had cycles off by 4294910021
[ 4870.748390] Clocksource hpet had cycles off by 4294958640
[ 4870.954498] Clocksource hpet had cycles off by 4294872876
[ 4872.812320] Clocksource hpet had cycles off by 4294885275
[ 4872.823645] Clocksource hpet had cycles off by 4294866238
[ 4872.867261] Clocksource hpet had cycles off by 4294957268
[ 4873.676168] Clocksource hpet had cycles off by 4294966242
[ 4877.229892] Clocksource hpet had cycles off by 4294883515
[ 4893.816464] Clocksource hpet had cycles off by 4294938409
[ 4894.318274] Clocksource hpet had cycles off by 4294908408
[ 4905.959500] Clocksource hpet had cycles off by 4294937652
[ 4924.827197] Clocksource hpet had cycles off by 4294957667
[ 4925.456653] Clocksource hpet had cycles off by 4294960141
[ 4932.326392] Clocksource hpet had cycles off by 4294907128
[ 4934.732113] Clocksource hpet had cycles off by 4294948395
[ 4934.743365] Clocksource hpet had cycles off by 4294930445
[ 4942.552790] Clocksource hpet had cycles off by 4294874035
[ 4945.457208] Clocksource hpet had cycles off by 4294929837
[ 4945.647660] Clocksource hpet had cycles off by 4294921846
[ 4950.555687] Clocksource hpet had cycles off by 4294909405
[ 4976.967578] Clocksource hpet had cycles off by 4294950121
[ 4979.117036] Clocksource hpet had cycles off by 4294940069
[ 5002.403831] Clocksource hpet had cycles off by 4294936372
[ 5020.353880] Clocksource hpet had cycles off by 4294930262
[ 5036.692914] Clocksource hpet had cycles off by 4294952001
[ 5045.171781] Clocksource hpet had cycles off by 4294898045
[ 5071.963409] Clocksource hpet had cycles off by 4294796101
[ 5078.613560] Clocksource hpet had cycles off by 4294882096
[ 5079.087553] Clocksource hpet had cycles off by 4294820969
[ 5081.004328] Clocksource hpet had cycles off by 4294851267
[ 5082.917976] Clocksource hpet had cycles off by 4294926333
[ 5087.054632] Clocksource hpet had cycles off by 4294939955
[ 5093.631733] Clocksource hpet had cycles off by 4294926983
[ 5094.330283] Clocksource hpet had cycles off by 4294941989
[ 5110.395745] Clocksource hpet had cycles off by 4294873876
[ 5110.435634] Clocksource hpet had cycles off by 4294875223
[ 5110.509490] Clocksource hpet had cycles off by 4294962589
[ 5110.589587] Clocksource hpet had cycles off by 4294960565
[ 5128.092220] Clocksource hpet had cycles off by 4294921061
[ 5132.569735] Clocksource hpet had cycles off by 4294919599
[ 5156.547880] Clocksource hpet had cycles off by 4294890788
[ 5159.944541] Clocksource hpet had cycles off by 4294910541
[ 5160.333493] Clocksource hpet had cycles off by 4294922199
[ 5162.315113] Clocksource hpet had cycles off by 4294882633
[ 5181.319714] Clocksource hpet had cycles off by 4294945810
[ 5182.884907] Clocksource hpet had cycles off by 4294858390
[ 5186.778012] Clocksource hpet had cycles off by 4294924884
[ 5197.855842] Clocksource hpet had cycles off by 4294864213
[ 5197.952885] Clocksource hpet had cycles off by 4294905809
[ 5198.679846] Clocksource hpet had cycles off by 4294943313
[ 5199.982167] Clocksource hpet had cycles off by 4294899268
[ 5204.351106] Clocksource hpet had cycles off by 4294878340
[ 5205.110198] Clocksource hpet had cycles off by 4294885031
[ 5209.299707] Clocksource hpet had cycles off by 4294857429
[ 5239.444653] Clocksource hpet had cycles off by 4294966446
[ 5255.008651] Clocksource hpet had cycles off by 4294923526
[ 5257.772678] Clocksource hpet had cycles off by 4294842949
[ 5259.896201] Clocksource hpet had cycles off by 4294918089
[ 5284.770634] Clocksource hpet had cycles off by 4294935032
[ 5302.299728] Clocksource hpet had cycles off by 4294945991
[ 5307.619643] Clocksource hpet had cycles off by 4294903178
[ 5315.291445] Clocksource hpet had cycles off by 4294957003
[ 5326.100708] Clocksource hpet had cycles off by 4294878037
[ 5338.598352] Clocksource hpet had cycles off by 4294951503
[ 5342.316899] Clocksource hpet had cycles off by 4294941428
[ 5344.665771] Clocksource hpet had cycles off by 4294938139
[ 5356.528904] Clocksource hpet had cycles off by 4294938129
[ 5380.477968] Clocksource hpet had cycles off by 4294896543
[ 5407.848043] Clocksource hpet had cycles off by 4294955079
[ 5410.097635] Clocksource hpet had cycles off by 4294942267
[ 5414.573618] Clocksource hpet had cycles off by 4294962698
[ 5414.983855] Clocksource hpet had cycles off by 4294955952
[ 5424.537540] Clocksource hpet had cycles off by 4294967133
[ 5425.499051] Clocksource hpet had cycles off by 4294937518
[ 5429.511923] Clocksource hpet had cycles off by 4294863228
[ 5430.414199] Clocksource hpet had cycles off by 4294823155
[ 5437.801616] Clocksource hpet had cycles off by 4294798993
[ 5468.287497] Clocksource hpet had cycles off by 4294891844
[ 5489.800970] Clocksource hpet had cycles off by 4294950293
[ 5510.281769] Clocksource hpet had cycles off by 4294912422
[ 5532.073472] Clocksource hpet had cycles off by 4294850674
[ 5549.445596] Clocksource hpet had cycles off by 4294962724
[ 5575.904611] Clocksource hpet had cycles off by 4294900881
[ 5579.483300] Clocksource hpet had cycles off by 4294889966
[ 5588.857974] Clocksource hpet had cycles off by 4294888621
[ 5589.455840] Clocksource hpet had cycles off by 4294914245
[ 5620.635120] Clocksource hpet had cycles off by 4294952529
[ 5620.928365] Clocksource hpet had cycles off by 4294903738
[ 5625.722839] Clocksource hpet had cycles off by 4294943093
[ 5631.856542] Clocksource hpet had cycles off by 4294839313
[ 5644.032367] Clocksource hpet had cycles off by 4294941402
[ 5647.813466] Clocksource hpet had cycles off by 4294894388
[ 5651.100292] Clocksource hpet had cycles off by 4294912467
[ 5678.273899] Clocksource hpet had cycles off by 4294922211
[ 5678.742115] Clocksource hpet had cycles off by 4294943849
[ 5695.958200] Clocksource hpet had cycles off by 4294857269
[ 5697.575874] Clocksource hpet had cycles off by 4294877152
[ 5705.158889] Clocksource hpet had cycles off by 4294914338
[ 5713.403739] Clocksource hpet had cycles off by 4294919820
[ 5729.534543] Clocksource hpet had cycles off by 4294917802
[ 5730.382999] Clocksource hpet had cycles off by 4294932957
[ 5742.686335] Clocksource hpet had cycles off by 4294926410
[ 5745.702133] Clocksource hpet had cycles off by 4294961654
[ 5746.141520] Clocksource hpet had cycles off by 4294966741
[ 5769.528576] Clocksource hpet had cycles off by 4294958417
[ 5784.972097] Clocksource hpet had cycles off by 4294923535
[ 5787.578966] Clocksource hpet had cycles off by 4294946783
[ 5813.633583] Clocksource hpet had cycles off by 4294951596
[ 5820.970202] Clocksource hpet had cycles off by 4294939310
[ 5830.287369] Clocksource hpet had cycles off by 4294902872
[ 5837.819734] Clocksource hpet had cycles off by 4294949911
[ 5838.588926] Clocksource hpet had cycles off by 4294954964
[ 5841.180607] Clocksource hpet had cycles off by 4294909572
[ 5848.836677] Clocksource hpet had cycles off by 4294902509
[ 5863.227184] Clocksource hpet had cycles off by 4294919298
[ 5884.519000] Clocksource hpet had cycles off by 4294860472
[ 5888.972993] Clocksource hpet had cycles off by 4294909499
[ 5909.998691] Clocksource hpet had cycles off by 4294797337
[ 5915.465763] Clocksource hpet had cycles off by 4294937155
[ 5915.924585] Clocksource hpet had cycles off by 4294950242
[ 5937.331075] Clocksource hpet had cycles off by 4294823436
[ 5943.651689] Clocksource hpet had cycles off by 4294905410
[ 5974.163191] Clocksource hpet had cycles off by 4294917888
[ 5977.359562] Clocksource hpet had cycles off by 4294943445
[ 5995.301687] Clocksource hpet had cycles off by 4294907800
[ 6029.468474] Clocksource hpet had cycles off by 4294957421
[ 6056.226569] Clocksource hpet had cycles off by 4294906619
[ 6062.484070] Clocksource hpet had cycles off by 4294890605
[ 6064.308707] Clocksource hpet had cycles off by 4294809203
[ 6098.279543] Clocksource hpet had cycles off by 4294802756
[ 6135.069521] Clocksource hpet had cycles off by 4294928208
[ 6135.285280] Clocksource hpet had cycles off by 4294843953
[ 6139.976491] Clocksource hpet had cycles off by 4294931068
[ 6143.423703] Clocksource hpet had cycles off by 4294942395
[ 6157.906601] Clocksource hpet had cycles off by 4294924337
[ 6177.083163] Clocksource hpet had cycles off by 4294958092
[ 6179.092624] Clocksource hpet had cycles off by 4294949225
[ 6214.012542] Clocksource hpet had cycles off by 4294947915
[ 6221.297576] Clocksource hpet had cycles off by 4294958776
[ 6226.018320] Clocksource hpet had cycles off by 4294909084
[ 6250.934516] Clocksource hpet had cycles off by 4294900612
[ 6260.946682] Clocksource hpet had cycles off by 4294929947
[ 6276.895078] Clocksource hpet had cycles off by 4294964159
[ 6283.232687] Clocksource hpet had cycles off by 4294945917
[ 6290.228100] Clocksource hpet had cycles off by 4294953716
[ 6297.087200] Clocksource hpet had cycles off by 4294909852
[ 6299.046671] Clocksource hpet had cycles off by 4294901253
[ 6299.187211] Clocksource hpet had cycles off by 4294892320
[ 6301.790171] Clocksource hpet had cycles off by 4294828528
[ 6306.810805] Clocksource hpet had cycles off by 4294921000
[ 6314.129911] Clocksource hpet had cycles off by 4294873175
[ 6327.787826] Clocksource hpet had cycles off by 4294790003
[ 6346.530949] Clocksource hpet had cycles off by 4294876632
[ 6370.781799] Clocksource hpet had cycles off by 4294950110
[ 6371.842423] Clocksource hpet had cycles off by 4294932421
[ 6374.793833] Clocksource hpet had cycles off by 4294887737
[ 6417.213990] Clocksource hpet had cycles off by 4294963984
[ 6418.003396] Clocksource hpet had cycles off by 4294822757
[ 6435.553685] Clocksource hpet had cycles off by 4294959791
[ 6464.638872] Clocksource hpet had cycles off by 4294931170
[ 6464.708534] Clocksource hpet had cycles off by 4294935528
[ 6468.948025] Clocksource hpet had cycles off by 4294907633
[ 6484.551740] Clocksource hpet had cycles off by 4294868507
[ 6484.699955] Clocksource hpet had cycles off by 4294892759
[ 6505.195090] Clocksource hpet had cycles off by 4294935944
[ 6515.271475] Clocksource hpet had cycles off by 4294904414
[ 6517.549058] Clocksource hpet had cycles off by 4294920126
[ 6519.321184] Clocksource hpet had cycles off by 4294875045
[ 6519.908060] Clocksource hpet had cycles off by 4294914921
[ 6527.724728] Clocksource hpet had cycles off by 4294897847
[ 6533.573475] Clocksource hpet had cycles off by 4294867477
[ 6557.035495] Clocksource hpet had cycles off by 4294930640
[ 6572.334089] Clocksource hpet had cycles off by 4294967233
[ 6574.727422] Clocksource hpet had cycles off by 4294899749
[ 6576.013240] Clocksource hpet had cycles off by 4294948971
[ 6588.328161] Clocksource hpet had cycles off by 4294776650
[ 6591.846962] Clocksource hpet had cycles off by 4294907791
[ 6591.890104] Clocksource hpet had cycles off by 4294862481
[ 6601.459236] Clocksource hpet had cycles off by 4294938828
[ 6610.623869] Clocksource hpet had cycles off by 4294939901
[ 6611.433532] Clocksource hpet had cycles off by 4294938116
[ 6633.251682] Clocksource hpet had cycles off by 4294927045
[ 6635.375075] Clocksource hpet had cycles off by 4294860954
[ 6656.878708] Clocksource hpet had cycles off by 4294917232
[ 6661.040050] Clocksource hpet had cycles off by 4294863572
[ 6662.034977] Clocksource hpet had cycles off by 4294927973
[ 6664.421749] Clocksource hpet had cycles off by 4294954448
[ 6672.247917] Clocksource hpet had cycles off by 4294944422
[ 6675.467838] Clocksource hpet had cycles off by 4294918962
[ 6677.270902] Clocksource hpet had cycles off by 4294860250
[ 6678.633280] Clocksource hpet had cycles off by 4294957945
[ 6685.963978] Clocksource hpet had cycles off by 4294887362
[ 6701.873035] Clocksource hpet had cycles off by 4294912353
[ 6702.662357] Clocksource hpet had cycles off by 4294915436
[ 6703.431587] Clocksource hpet had cycles off by 4294920195
[ 6704.522236] Clocksource hpet had cycles off by 4294901823
[ 6713.083410] Clocksource hpet had cycles off by 4294957243
[ 6713.114765] Clocksource hpet had cycles off by 4294937637
[ 6716.082258] Clocksource hpet had cycles off by 4294948909
[ 6718.203099] Clocksource hpet had cycles off by 4294919408
[ 6718.971994] Clocksource hpet had cycles off by 4294928882
[ 6720.708849] Clocksource hpet had cycles off by 4294959583
[ 6721.028787] Clocksource hpet had cycles off by 4294957753
[ 6726.836580] Clocksource hpet had cycles off by 4294941202
[ 6727.583387] Clocksource hpet had cycles off by 4294837664
[ 6742.105971] Clocksource hpet had cycles off by 4294966775
[ 6758.356617] Clocksource hpet had cycles off by 4294966130
[ 6762.800567] Clocksource hpet had cycles off by 4294872687
[ 6777.845714] Clocksource hpet had cycles off by 4294960889
[ 6798.288427] Clocksource hpet had cycles off by 4294895965
[ 6798.514300] Clocksource hpet had cycles off by 4294953069
[ 6798.734637] Clocksource hpet had cycles off by 4294803356
[ 6799.934953] Clocksource hpet had cycles off by 4294932050
[ 6804.485824] Clocksource hpet had cycles off by 4294881922
[ 6830.087641] Clocksource hpet had cycles off by 4294930326
[ 6838.518600] Clocksource hpet had cycles off by 4294846768
[ 6857.801095] Clocksource hpet had cycles off by 4294937726
[ 6898.388286] Clocksource hpet had cycles off by 4294785053
[ 6907.121034] Clocksource hpet had cycles off by 4294816610
[ 6926.043057] Clocksource hpet had cycles off by 4294917312
[ 6926.803442] Clocksource hpet had cycles off by 4294905471
[ 6927.075925] Clocksource hpet had cycles off by 4294867702
[ 6929.839822] Clocksource hpet had cycles off by 4294932181
[ 6954.442526] Clocksource hpet had cycles off by 4294832962
[ 6966.174058] Clocksource hpet had cycles off by 4294857017
[ 6968.395284] Clocksource hpet had cycles off by 4294964282
[ 6978.293338] Clocksource hpet had cycles off by 4294910164
[ 7020.205322] Clocksource hpet had cycles off by 4294964231
[ 7031.379481] Clocksource hpet had cycles off by 4294955343
[ 7038.454684] Clocksource hpet had cycles off by 4294965434
[ 7039.017680] Clocksource hpet had cycles off by 4294917868
[ 7066.359342] Clocksource hpet had cycles off by 4294954047
[ 7068.741632] Clocksource hpet had cycles off by 4294901425
[ 7083.980073] Clocksource hpet had cycles off by 4294940744
[ 7088.905444] Clocksource hpet had cycles off by 4294966277
[ 7099.930773] Clocksource hpet had cycles off by 4294941903
[ 7105.897852] Clocksource hpet had cycles off by 4294934229
[ 7110.933612] Clocksource hpet had cycles off by 4294953279
[ 7129.072933] Clocksource hpet had cycles off by 4294955897
[ 7129.767004] Clocksource hpet had cycles off by 4294891957
[ 7156.722538] Clocksource hpet had cycles off by 4294875889
[ 7179.913404] Clocksource hpet had cycles off by 4294957740
[ 7189.328997] Clocksource hpet had cycles off by 4294942902
[ 7210.145915] Clocksource hpet had cycles off by 4294957773
[ 7236.795287] Clocksource hpet had cycles off by 4294889295
[ 7243.509122] Clocksource hpet had cycles off by 4294922023
[ 7271.875409] Clocksource hpet had cycles off by 4294740258
[ 7297.285172] Clocksource hpet had cycles off by 4294962657
[ 7310.990716] Clocksource hpet had cycles off by 4294912929
[ 7312.084582] Clocksource hpet had cycles off by 4294848642
[ 7314.470384] Clocksource hpet had cycles off by 4294889002
[ 7315.035741] Clocksource hpet had cycles off by 4294950647
[ 7315.307236] Clocksource hpet had cycles off by 4294927050
[ 7317.355527] Clocksource hpet had cycles off by 4294934516
[ 7317.507286] Clocksource hpet had cycles off by 4294908108
[ 7332.817230] Clocksource hpet had cycles off by 4294925346
[ 7340.929623] Clocksource hpet had cycles off by 4294966964
[ 7379.138915] Clocksource hpet had cycles off by 4294947109
[ 7382.226767] Clocksource hpet had cycles off by 4294809185
[ 7386.444425] Clocksource hpet had cycles off by 4294950895
[ 7409.150469] Clocksource hpet had cycles off by 4294962611
[ 7426.042688] Clocksource hpet had cycles off by 4294934167
[ 7426.082070] Clocksource hpet had cycles off by 4294942677
[ 7430.354331] Clocksource hpet had cycles off by 4294874886
[ 7434.067328] Clocksource hpet had cycles off by 4294944448
[ 7436.374986] Clocksource hpet had cycles off by 4294958881
[ 7437.165057] Clocksource hpet had cycles off by 4294951297
[ 7437.576178] Clocksource hpet had cycles off by 4294931847
[ 7469.267601] Clocksource hpet had cycles off by 4294935388
[ 7472.926004] Clocksource hpet had cycles off by 4294927961
[ 7473.035131] Clocksource hpet had cycles off by 4294939573
[ 7477.606732] Clocksource hpet had cycles off by 4294878650
[ 7484.316221] Clocksource hpet had cycles off by 4294830436
[ 7485.829596] Clocksource hpet had cycles off by 4294912868
[ 7489.836062] Clocksource hpet had cycles off by 4294930459
[ 7517.439309] Clocksource hpet had cycles off by 4294941503
[ 7518.214518] Clocksource hpet had cycles off by 4294860491
[ 7528.973593] Clocksource hpet had cycles off by 4294927857
[ 7538.526153] Clocksource hpet had cycles off by 4294955154
[ 7540.727143] Clocksource hpet had cycles off by 4294922835
[ 7541.785108] Clocksource hpet had cycles off by 4294943237
[ 7547.270907] Clocksource hpet had cycles off by 4294957904
[ 7548.399906] Clocksource hpet had cycles off by 4294962899
[ 7553.329945] Clocksource hpet had cycles off by 4294921515
[ 7558.594497] Clocksource hpet had cycles off by 4294955867
[ 7571.296453] Clocksource hpet had cycles off by 4294965875
[ 7572.297917] Clocksource hpet had cycles off by 4294936696
[ 7584.129477] Clocksource hpet had cycles off by 4294959463
[ 7631.334389] Clocksource hpet had cycles off by 4294927694
[ 7658.144277] Clocksource hpet had cycles off by 4294850625
[ 7665.387109] Clocksource hpet had cycles off by 4294893204
[ 7714.453000] Clocksource hpet had cycles off by 4294831930
[ 7739.171354] Clocksource hpet had cycles off by 4294937098
[ 7749.445785] Clocksource hpet had cycles off by 4294931693
[ 7764.919405] Clocksource hpet had cycles off by 4294895069
[ 7772.220322] Clocksource hpet had cycles off by 4294965063
[ 7775.778338] Clocksource hpet had cycles off by 4294963388
[ 7792.889439] Clocksource hpet had cycles off by 4294949185
[ 7797.879080] Clocksource hpet had cycles off by 4294912987
[ 7800.596555] Clocksource hpet had cycles off by 4294926575
[ 7811.046111] Clocksource hpet had cycles off by 4294846442
[ 7817.048445] Clocksource hpet had cycles off by 4294906500
[ 7822.443159] Clocksource hpet had cycles off by 4294937437
[ 7849.680883] Clocksource hpet had cycles off by 4294887672
[ 7854.373766] Clocksource hpet had cycles off by 4294950629
[ 7863.277494] Clocksource hpet had cycles off by 4294966728
[ 7863.477635] Clocksource hpet had cycles off by 4294962968
[ 7864.313563] Clocksource hpet had cycles off by 4294871251
[ 7865.821339] Clocksource hpet had cycles off by 4294890597
[ 7876.291192] Clocksource hpet had cycles off by 4294949092
[ 7879.888696] Clocksource hpet had cycles off by 4294955026
[ 7910.026184] Clocksource hpet had cycles off by 4294884664
[ 7915.601307] Clocksource hpet had cycles off by 4294908311
[ 7920.607557] Clocksource hpet had cycles off by 4294920518
[ 7932.572470] Clocksource hpet had cycles off by 4294894280
[ 7937.241556] Clocksource hpet had cycles off by 4294868692
[ 7940.775581] Clocksource hpet had cycles off by 4294924933
[ 7949.147913] Clocksource hpet had cycles off by 4294965384
[ 7950.379028] Clocksource hpet had cycles off by 4294939201
[ 7999.898462] Clocksource hpet had cycles off by 4294966898
[ 8000.239317] Clocksource hpet had cycles off by 4294951726
[ 8007.101739] Clocksource hpet had cycles off by 4294860141
[ 8018.431564] Clocksource hpet had cycles off by 4294912041
[ 8038.027568] Clocksource hpet had cycles off by 4294950192
[ 8069.892109] Clocksource hpet had cycles off by 4294764480
[ 8101.450098] Clocksource hpet had cycles off by 4294961535
[ 8101.786097] Clocksource hpet had cycles off by 4294872842
[ 8102.842211] Clocksource hpet had cycles off by 4294776561
[ 8103.965146] Clocksource hpet had cycles off by 4294868328
[ 8122.896036] Clocksource hpet had cycles off by 4294842099
[ 8149.283965] Clocksource hpet had cycles off by 4294939642
[ 8154.503130] Clocksource hpet had cycles off by 4294908378
[ 8165.305183] Clocksource hpet had cycles off by 4294932669
[ 8171.667909] Clocksource hpet had cycles off by 4294840995
[ 8196.928476] Clocksource hpet had cycles off by 4294910078
[ 8229.599255] Clocksource hpet had cycles off by 4294914687
[ 8239.193123] Clocksource hpet had cycles off by 4294923080
[ 8239.650541] Clocksource hpet had cycles off by 4294956286
[ 8239.947251] Clocksource hpet had cycles off by 4294857682
[ 8241.924557] Clocksource hpet had cycles off by 4294879976
[ 8245.030679] Clocksource hpet had cycles off by 4294909712
[ 8251.775849] Clocksource hpet had cycles off by 4294922984
[ 8263.898042] Clocksource hpet had cycles off by 4294934385
[ 8266.278976] Clocksource hpet had cycles off by 4294901363
[ 8281.454261] Clocksource hpet had cycles off by 4294843228
[ 8285.870006] Clocksource hpet had cycles off by 4294867567
[ 8298.621180] Clocksource hpet had cycles off by 4294888436
[ 8298.757273] Clocksource hpet had cycles off by 4294943246
[ 8308.035690] Clocksource hpet had cycles off by 4294889036
[ 8311.154045] Clocksource hpet had cycles off by 4294886733
[ 8312.848648] Clocksource hpet had cycles off by 4294949960
[ 8312.863102] Clocksource hpet had cycles off by 4294886142
[ 8315.476778] Clocksource hpet had cycles off by 4294954936
[ 8318.814522] Clocksource hpet had cycles off by 4294959686
[ 8319.834864] Clocksource hpet had cycles off by 4294946289
[ 8349.397739] Clocksource hpet had cycles off by 4294946741
[ 8382.389404] Clocksource hpet had cycles off by 4294935992
[ 8408.794696] Clocksource hpet had cycles off by 4294927930
[ 8410.900853] Clocksource hpet had cycles off by 4294965564
[ 8424.086268] Clocksource hpet had cycles off by 4294921997
[ 8427.317733] Clocksource hpet had cycles off by 4294874276
[ 8444.811443] Clocksource hpet had cycles off by 4294962606
[ 8445.113445] Clocksource hpet had cycles off by 4294931560
[ 8462.581299] Clocksource hpet had cycles off by 4294960739
[ 8462.715757] Clocksource hpet had cycles off by 4294895796
[ 8493.622948] Clocksource hpet had cycles off by 4294966474
[ 8494.833670] Clocksource hpet had cycles off by 4294946137
[ 8501.019390] Clocksource hpet had cycles off by 4294956147
[ 8533.765179] Clocksource hpet had cycles off by 4294888459
[ 8538.547991] Clocksource hpet had cycles off by 4294808556
[ 8554.721417] Clocksource hpet had cycles off by 4294911891
[ 8556.567332] Clocksource hpet had cycles off by 4294955177
[ 8558.766400] Clocksource hpet had cycles off by 4294950299
[ 8576.729899] Clocksource hpet had cycles off by 4294894690
[ 8603.246371] Clocksource hpet had cycles off by 4294868839
[ 8632.497979] Clocksource hpet had cycles off by 4294889916
[ 8642.138536] Clocksource hpet had cycles off by 4294945200
[ 8643.223516] Clocksource hpet had cycles off by 4294864937
[ 8672.322200] Clocksource hpet had cycles off by 4294929168
[ 8690.759412] Clocksource hpet had cycles off by 4294959493
[ 8709.492255] Clocksource hpet had cycles off by 4294907059
[ 8724.280863] Clocksource hpet had cycles off by 4294947618
[ 8733.784764] Clocksource hpet had cycles off by 4294956463
[ 8736.674757] Clocksource hpet had cycles off by 4294932319
[ 8739.246240] Clocksource hpet had cycles off by 4294889784
[ 8744.718494] Clocksource hpet had cycles off by 4294955354
[ 8748.845567] Clocksource hpet had cycles off by 4294963121
[ 8756.253080] Clocksource hpet had cycles off by 4294937365
[ 8762.767729] Clocksource hpet had cycles off by 4294960073
[ 8785.657751] Clocksource hpet had cycles off by 4294913298
[ 8808.529748] Clocksource hpet had cycles off by 4294838591
[ 8813.760909] Clocksource hpet had cycles off by 4294921712
[ 8815.321019] Clocksource hpet had cycles off by 4294907336
[ 8818.077544] Clocksource hpet had cycles off by 4294934173
[ 8838.651774] Clocksource hpet had cycles off by 4294846372
[ 8840.092610] Clocksource hpet had cycles off by 4294965757
[ 8841.833566] Clocksource hpet had cycles off by 4294937637
[ 8868.628460] Clocksource hpet had cycles off by 4294932050
[ 8874.366140] Clocksource hpet had cycles off by 4294917706
[ 8874.732828] Clocksource hpet had cycles off by 4294962074
[ 8880.059558] Clocksource hpet had cycles off by 4294964809
[ 8891.447021] Clocksource hpet had cycles off by 4294906820
[ 8896.750796] Clocksource hpet had cycles off by 4294951994
[ 8898.189306] Clocksource hpet had cycles off by 4294961458
[ 8898.709462] Clocksource hpet had cycles off by 4294954950
[ 8899.369753] Clocksource hpet had cycles off by 4294945259
[ 8928.971992] Clocksource hpet had cycles off by 4294954376
[ 8929.021722] Clocksource hpet had cycles off by 4294957830
[ 8936.577523] Clocksource hpet had cycles off by 4294955418
[ 8936.687488] Clocksource hpet had cycles off by 4294954959
[ 8937.019020] Clocksource hpet had cycles off by 4294930347
[ 8937.042867] Clocksource hpet had cycles off by 4294875044
[ 8941.655197] Clocksource hpet had cycles off by 4294946703
[ 8943.261263] Clocksource hpet had cycles off by 4294846525
[ 8949.283066] Clocksource hpet had cycles off by 4294914024
[ 9002.000288] Clocksource hpet had cycles off by 4294946758
[ 9027.774997] Clocksource hpet had cycles off by 4294952261
[ 9032.419466] Clocksource hpet had cycles off by 4294849853
[ 9033.882828] Clocksource hpet had cycles off by 4294789534
[ 9054.591077] Clocksource hpet had cycles off by 4294929529
[ 9055.470296] Clocksource hpet had cycles off by 4294933377
[ 9070.914430] Clocksource hpet had cycles off by 4294889478
[ 9088.885051] Clocksource hpet had cycles off by 4294874940
[ 9091.500745] Clocksource hpet had cycles off by 4294914900
[ 9123.008947] Clocksource hpet had cycles off by 4294966056
[ 9144.431073] Clocksource hpet had cycles off by 4294901401
[ 9146.349907] Clocksource hpet had cycles off by 4294902199
[ 9149.985011] Clocksource hpet had cycles off by 4294942253
[ 9159.173212] Clocksource hpet had cycles off by 4294891821
[ 9159.706348] Clocksource hpet had cycles off by 4294842545
[ 9165.735597] Clocksource hpet had cycles off by 4294946486
[ 9184.604714] Clocksource hpet had cycles off by 4294946134
[ 9190.991487] Clocksource hpet had cycles off by 4294939336
[ 9224.390628] Clocksource hpet had cycles off by 4294961394
[ 9231.459587] Clocksource hpet had cycles off by 4294944626
[ 9241.941939] Clocksource hpet had cycles off by 4294940579
[ 9242.801999] Clocksource hpet had cycles off by 4294932526
[ 9260.811589] Clocksource hpet had cycles off by 4294932405
[ 9261.491175] Clocksource hpet had cycles off by 4294932739
[ 9268.155226] Clocksource hpet had cycles off by 4294819608
[ 9287.714075] Clocksource hpet had cycles off by 4294960443

Hmm. So my patch is a bit sloppy, and I suspect that the sloppiness may account for some - and quite probably all - of those numbers.

Some of your numbers are pretty big (it's a 32-bit mask, so they are all really just pretty small negative numbers), but they are still in the 2us .. 165ms range when taking the 14MHz HPET counter into account. So not huge timer shifts.

And the sloppiness of the patch is two-fold:

One problem with my patch is that it does that "tkr->cycle_error" without any locking (because it's running in various environmetns where locking really doesn't work, and we can't even sanely disable preemption because we might well be inside the scheduler etc.

So this:

          cycle_now = tkr->read(tkr->clock) + tkr->cycle_error;

          /* calculate the delta since the last update_wall_time: */
          delta = clocksource_delta(cycle_now, tkr->cycle_last, tkr->mask);

          /* Hmm? This is really not good, we're too close to overflowing */
          if (unlikely(delta > (tkr->mask >> 3))) {
                  tkr->cycle_error = delta;
                 delta = 0;
          }

might run concurrently on two CPU's, and then that tkr->cycle_error access isn't serialized, so a "later" read of the HPET clock could end up being written to tkr->cycle_error before. So that can account for small errors: you'd have a "cycle_error" that gets updated on one CPU, and then used to correct for an "earlier" read of the clock on another CPU, and that could make the cycle error possibly worse.

However, that first race only matters if you get errors to begin with, so if that was the only race, it would still show that some real error happened.

BUT.

The *bigger* problem is that since the reading side cannot hold any locks at all, it can also race against the writing side. That's by design, and we will use the sequence counter to recover from it and try again, but it means that some of those small errors are just a reader racing with the wall-time update code, and since this error code is done _inside_ the read-sequence code, it's not aware of the retry, and will give a false positive even if we then later on throw the known-bad result out and re-try.

So your small negative numbers are most likely just those false positives.

I was more hoping to see some big sudden jumps on the order of your 20-second delays - the kinds of jumps that your "tsc unstable" messages implied (which weren't in the 2us .. 165ms range, but in the 2s to 250s range)

Ugh. I guess I'll have to try to figure out a non-sloppy thing, but quite frankly, the non-sloppy things I tried first were rather painful failures. The sloppy thing was sloppy, but worked well to see the disaster case.

I'll put on my thinking cap. Maybe I can move the "cycle_error" logic to outside the sequence lock retry loop.

But in the meantime please do keep that thing running as long as you can. Let's see if we get bigger jumps. Or perhaps we'll get a negative result - the original softlockup bug happening *without* any bigger hpet jumps.

Linus

It's been going for 18 hours, with just a bunch more of those hpet messages, all in the same range. I'll leave it go a few more hours, before I have to wipe it, but I've got feel-good vibes about this. Even if that patch isn't the solution, It seems like we're finally looking in the right direction.

Dave

I've got myself a physical server to play with, and running trinity on it seems to cause similar stalls:

2338.389210] INFO: rcu_sched self-detected stall on CPU[ 2338.429153] INFO: rcu_sched detected stalls on CPUs/tasks:[ 2338.429164] 16: (5999 ticks this GP) idle=4b5/140000000000001/0 softirq=24859/24860 last_accelerate: 039d/1b78, nonlazy_posted: 64, ..

[ 2338.429165] 	
[ 2338.680231] 	16: (5999 ticks this GP) idle=4b5/140000000000001/0 softirq=24859/24860 last_accelerate: 039d/1b91, nonlazy_posted: 64, ..
[ 2338.828353] 	 (t=6044 jiffies g=16473 c=16472 q=4915881)

Oddly enough, there's no stacktrace...

Thanks,
Sasha

So I've got this box a *little* longer than anticipated. It's now been running 30 hours with not a single NMI lockup. and that's with my kitchen-sink debugging kernel.

The 'hpet off' messages continue to be spewed, and again they're all in the same range of 4293198075 -> 4294967266

Dave

In case there was any doubt remaining, it's now been running 3 days, 20 hours with no lockups at all. I haven't seen it run this long in months.

Either tomorrow or Sunday I'm finally wiping that box to give it back on Monday, so if there's anything else you'd like to try, the next 24hrs are pretty much the only remaining time I have.

One thing I think I'll try is to try and narrow down which syscalls are triggering those "Clocksource hpet had cycles off" messages. I'm still unclear on exactly what is doing the stomping on the hpet.

Dave

First I ran trinity with "-g vm" which limits it to use just a subset of syscalls, specifically VM related ones. That triggered the messages. Further experiments revealed:

-c mremap triggered it, but only when I also passed -C256 to crank up the number of child processes. The same thing occured with mprotect, madvise, remap_file_pages.

I couldn't trigger it with -c mmap, or msync, mbind, move_pages, migrate_pages, mlock, regardless of how many child processes there were.

Given the high child count necessary to trigger it, it's nigh on impossible to weed through all the calls that trinity made to figure out which one actually triggered the messages.

I'm not even convinced that the syscall parameters are even particularly interesting. The "needs high load to trigger" aspect of the bug still has a smell of scheduler interaction or side effect of lock contention. Looking at one childs syscall params in isolation might look quite dull, but if we have N processes hammering on the same mapping, that's probably a lot more interesting.

Dave

So I can trigger the false positives with my original patch quite easily by just putting my box under some load. My numbers are nowhere near as bad as yours, but then, I didn't put it under as much load anyway. Just a regular "make -j64" of the kernel.

I suspect your false positives are bigger partly because of the load, but mostly because you presumably have preemption enabled too. I don't do preemption in my normal kernels, and that limits the damage of the race a bit.

I have a newer version of the patch that gets rid of the false positives with some ordering rules instead, and just for you I hacked it up to say where the problem happens too, but it's likely too late.

The fact that the original racy patch seems to make a difference for you does say that yes, we seem to be zeroing in on the right area here, but I'm not seeing what's wrong. I was hoping for big jumps from your HPET, since your "TSC unstable" messages do kind of imply that such really big jumps can happen.

I'm attaching my updated hacky patch, although I assume it's much too late for that machine. Don't look too closely at the backtrace generation part, that's just a quick hack, and only works with frame pointers enabled anyway.

So I'm still a bit unhappy about not figuring out *what* is wrong. And I'd still like the dmidecode from that machine, just for posterity. In case we can figure out some pattern.

So right now I can imagine several reasons:

- actual hardware bug.

This is *really* unlikely, though. It should hit everybody. The
HPET is in the core intel chipset, we're not talking random unusual hardware by fly-by-night vendors here.

- some SMM/BIOS "power management" feature.

We've seen this before, where the SMM saves/restores the TSC on
entry/exit in order to hide itself from the system. I could imagine similar code for the HPET counter. SMM writers use some bad drugs to dull their pain.

And with the HPET counter, since it's not even per-CPU, the "save
and restore HPET" will actually show up as "HPET went backwards" to the other non-SMM CPU's if it happens

- a bug in our own clocksource handling.

I'm not seeing it. But maybe my patch hides it for some magical reason.

- gremlins.

So I dunno. I hope more people will look at this after the holidays, even if your machine is gone. My test-program to do bad things to the HPET shows *something*, and works on any machine.

Linus

 arch/x86/kernel/entry_64.S          |  5 +++
 include/linux/timekeeper_internal.h |  1 +
 kernel/time/timekeeping.c           | 78 +++++++++++++++++++++++++++++++++++--
 3 files changed, 81 insertions(+), 3 deletions(-)

index 9ebaf63ba182..0a4c34b4658e 100644
@@ -312,6 +312,11 @@ ENTRY(save_paranoid)
 	CFI_ENDPROC
 END(save_paranoid)
 
+ENTRY(save_back_trace)
+	movq %rbp,%rdi
+	jmp do_save_back_trace
+END(save_back_trace)
+
 /*
  * A newly forked process directly context switches into this address.
  *

index 05af9a334893..0fcb60d77079 100644
@@ -32,6 +32,7 @@ struct tk_read_base {
 	cycle_t			(*read)(struct clocksource *cs);
 	cycle_t			mask;
 	cycle_t			cycle_last;
+	cycle_t			cycle_error;
 	u32			mult;
 	u32			shift;
 	u64			xtime_nsec;

I'll give it a spin and see what falls out this evening.

So this is something I should have done a long time ago. Googling for the board name shows up a very similar report from a year ago, except that was within kvm, and was aparently fixed.
https://lkml.org/lkml/2013/10/9/206 and
https://bugzilla.kernel.org/show_bug.cgi?id=69491
(dmidecode attachment there is pretty much the same as mine)

This machine is allegedly a 'production' box from Intel, but given Kashyap saw something very similar I'm wondering now if there was some board/bios errata for this system.

There's a few Intel folks cc'd here, maybe one those can dig up whether there was anything peculiar about Shark Bay systems that would explain the HPET getting screwed up.

Dave

hm.

[ 2733.047100] INFO: rcu_preempt detected stalls on CPUs/tasks:
[ 2733.047188] 	Tasks blocked on level-0 rcu_node (CPUs 0-7): P25811
[ 2733.047216] 	Tasks blocked on level-0 rcu_node (CPUs 0-7): P25811
[ 2733.047242] 	(detected by 0, t=6502 jiffies, g=52141, c=52140, q=0)
[ 2733.047271] trinity-c406    R  running task    13416 25811  24907 0x00000000
[ 2733.047305]  ffff88022208fd28 0000000000000002 ffffffffa819f627 ffff8801df2c0000
[ 2733.047341]  00000000001d31c0 0000000000000002 ffff88022208ffd8 00000000001d31c0
[ 2733.047375]  ffff8800806e1780 ffff8801df2c0000 ffff88022208fd18 ffff88022208ffd8
[ 2733.047411] Call Trace:
[ 2733.047429]  [<ffffffffa819f627>] ? context_tracking_user_exit+0x67/0x280
[ 2733.047457]  [<ffffffffa88522a2>] preempt_schedule_irq+0x52/0xb0
[ 2733.047482]  [<ffffffffa8859820>] retint_kernel+0x20/0x30
[ 2733.047505]  [<ffffffffa808a361>] ? check_kill_permission+0xb1/0x1e0
[ 2733.047531]  [<ffffffffa808a402>] ? check_kill_permission+0x152/0x1e0
[ 2733.047557]  [<ffffffffa808dc25>] group_send_sig_info+0x65/0x150
[ 2733.047581]  [<ffffffffa808dbc5>] ? group_send_sig_info+0x5/0x150
[ 2733.047607]  [<ffffffffa80ed71e>] ? rcu_read_lock_held+0x6e/0x80
[ 2733.047632]  [<ffffffffa808dee8>] kill_pid_info+0x78/0x130
[ 2733.047654]  [<ffffffffa808de75>] ? kill_pid_info+0x5/0x130
[ 2733.047677]  [<ffffffffa808e0b2>] SYSC_kill+0xf2/0x2f0
[ 2733.047699]  [<ffffffffa808e05b>] ? SYSC_kill+0x9b/0x2f0
[ 2733.047721]  [<ffffffffa80d7ffd>] ? trace_hardirqs_on+0xd/0x10
[ 2733.047745]  [<ffffffffa8013765>] ? syscall_trace_enter_phase1+0x125/0x1a0
[ 2733.048607]  [<ffffffffa80d7f2d>] ? trace_hardirqs_on_caller+0x10d/0x1d0
[ 2733.049469]  [<ffffffffa809079e>] SyS_kill+0xe/0x10
[ 2733.050332]  [<ffffffffa8858aa2>] system_call_fastpath+0x12/0x17
[ 2733.051197] trinity-c406    R  running task    13416 25811  24907 0x00000000
[ 2733.052064]  ffff88022208fd28 0000000000000002 ffffffffa819f627 ffff8801df2c0000
[ 2733.052932]  00000000001d31c0 0000000000000002 ffff88022208ffd8 00000000001d31c0
[ 2733.053792]  ffff880209e2c680 ffff8801df2c0000 ffff88022208fd18 ffff88022208ffd8
[ 2733.054651] Call Trace:
[ 2733.055500]  [<ffffffffa819f627>] ? context_tracking_user_exit+0x67/0x280
[ 2733.056362]  [<ffffffffa88522a2>] preempt_schedule_irq+0x52/0xb0
[ 2733.057222]  [<ffffffffa8859820>] retint_kernel+0x20/0x30
[ 2733.058076]  [<ffffffffa808a361>] ? check_kill_permission+0xb1/0x1e0
[ 2733.058930]  [<ffffffffa808a402>] ? check_kill_permission+0x152/0x1e0
[ 2733.059778]  [<ffffffffa808dc25>] group_send_sig_info+0x65/0x150
[ 2733.060624]  [<ffffffffa808dbc5>] ? group_send_sig_info+0x5/0x150
[ 2733.061472]  [<ffffffffa80ed71e>] ? rcu_read_lock_held+0x6e/0x80
[ 2733.062322]  [<ffffffffa808dee8>] kill_pid_info+0x78/0x130
[ 2733.063168]  [<ffffffffa808de75>] ? kill_pid_info+0x5/0x130
[ 2733.064015]  [<ffffffffa808e0b2>] SYSC_kill+0xf2/0x2f0
[ 2733.064863]  [<ffffffffa808e05b>] ? SYSC_kill+0x9b/0x2f0
[ 2733.065704]  [<ffffffffa80d7ffd>] ? trace_hardirqs_on+0xd/0x10
[ 2733.066541]  [<ffffffffa8013765>] ? syscall_trace_enter_phase1+0x125/0x1a0
[ 2733.067384]  [<ffffffffa80d7f2d>] ? trace_hardirqs_on_caller+0x10d/0x1d0
[ 2733.068217]  [<ffffffffa809079e>] SyS_kill+0xe/0x10
[ 2733.069045]  [<ffffffffa8858aa2>] system_call_fastpath+0x12/0x17
[ 3708.217920] perf interrupt took too long (2503 > 2500), lowering kernel.perf_event_max_sample_rate to 50000
[ 4583.530580] request_module: runaway loop modprobe personality-87

still running though..

Dave

So with the previous patch that had the false positives, you never saw this? You saw the false positives instead?

I'm wondering if the added debug noise just ended up helping. Doing a printk() will automatically cause some scheduler activity. And they also caused the time reading jiggle.

That said, it's also possible that I screwed something up in the second version of the patch, just breaking it and making it generally ineffective.

Oh - and have you actually seen the "TSC unstable (delta = xyz)" + "switched to hpet" messages there yet?

Linus

correct.

not yet. 3 hrs in.

Dave

Ok, so then the

     INFO: rcu_preempt detected stalls on CPUs/tasks:

has nothing to do with HPET, since you'd still be running with the TSC enabled.

My googling around did find a number of "machine locks up a few hours after switching to hpet" reports, so it is possible that the whole rcu stall and nmi watchdog thing is independent and unrelated to the actual locking up.

It *is* intriguing that my broken patch seemed to prevent it from happening, though. And both NMI watchdogs and the rcu stall are related to wall-clock time. But hey, maybe there really is some odd loop in the kernel that stops scheduling or RCU grace periods. It just seems to be never caught by your backtraces..

Linus

right. 16hrs later, that's the only thing that's spewed.

possible. I'm heading home in a few hours to start the wipe of that box. This is going to be 'the one that got away', but at least we've managed to find a number of other things that needed fixing along the way.

Dave

Btw, did you ever boot with "tsc=reliable" as a kernel command line option?

For the last night, can you see if you can just run it with that, and things work? Because by now, my gut feel is that we should start derating the HPET rather than the TSC, especially going forward on modern hardware. And if this is some subtle timing issue with our hpet code (the whole -ETIME thing when getting close to setting a timer is subtle, for example, even if the HPET hardware itself would be ok), I'm wondering if the fix isn't to just stop believing in HPET if there are better alternatives around.

So I'm not even convinced that trying to debug some HPET issue is really worth it. Especially if your machine is a preproduction board from Intel.

But verifying that with just the TSC everything is ok might still be worth it.

Linus

I don't think so.

Sure.

Yeah, I agree. Even though it's strange that this only became a problem this last few months for me, after over a year of abuse.

Hopefully the new year brings more trustworthy hardware.

Dave

I'll check it again in the morning, but before I turn in for the night, so far the only thing is this:

[ 6713.394395] INFO: rcu_preempt detected stalls on CPUs/tasks:
[ 6713.394489] 	Tasks blocked on level-0 rcu_node (CPUs 0-7):
[ 6713.394513] 	Tasks blocked on level-0 rcu_node (CPUs 0-7):
[ 6713.394536] 	(detected by 3, t=6502 jiffies, g=141292, c=141291, q=0)
[ 6713.394564] INFO: Stall ended before state dump start

Dave

So I sent out a first step validation check to warn us if we end up with idle periods that are larger then we expect.

It doesn't yet cap the timekeeping_get_ns() output (like you're patch effectively does), but it would be easy to do that in a following patch.

I did notice while testing this that the max_idle_ns (max idle time we report to the scheduler) for the hpet is only ~16sec, and we'll overflow after just ~21seconds. This second number maps closely to the 22 second stalls seen in the nmi watchdog reports which seems interesting, but I also realize that qemu uses a 100MHz hpet, where as real hardware is likely to be a bit slower, so maybe that's just chance..

I'd be interested if folks seeing anything similar to Dave would give my patch a shot.

thanks
-john

I ran it overnight, but I didn't see any of the new warnings in the logs.

Thanks,
Sasha

.. not having tested it, this is just from reading the patch, but it would *seem* that it doesn't actually validate the clock reading much at all.

Why? Because most of the time, for crap clocks like HPET, the real limitation will be not the multiplication overflow, but the "mask", which is just 32-bit (or worse - I think the ACPI PM timer might be just 24 bits).

So then you effectively "validate" that the timer difference value fits in mask, but that isn't any validation at all - it's just a truism. Since we by definition mask the difference to just the valid bitmask.

So I really think that the maximum valid clock needs to be narrowed down from the "technically, this clock can count to X".

But maybe I'm wrong, and the multiplication overflow is actually often the real limit. What are the actual values for real timer sources?

Linus

As you point out, for clocksources where the mask is 32bits or under, we shouldn't have any risk of multiplication overflow, since mult is a 32bit. So yes, the max_cycles on those probably should be the same as the mask, and isn't useful on those clocksources to test if we run over (though warning if we're within the 12% margin could be useful). But for clocksources who have larger masks, it still could be a useful check (@2ghz tscs overflow 32bits in 2 seconds), although the mult value is targets an mult overflow at ~10 minutes, so its less likely that we really hit it.

However, it ends up the calculations we use are a little more conservative, treating the result as signed and so they avoid multiplications that could run into a that sign bit. This looks like an error to me (the code is also used for clockevents, so I haven't run through to see if the requirements are different there), but a conservative one, which results in the maximum idle interval to be ~halved what they could be (and we add yet another 12% margin on that
- so we probably need to just pick one or the other, not both).

So even on 32bit masks, max_cycles in my patch is smaller then 32bits. That's why I was able to hit both warnings in my testing with the hpet by sending SIGSTOP to qemu.

Anyway, It may be worth keeping the 50% margin (and dropping the 12% reduction to simplify things), since I've not heard recent complaints about timekeeping limiting idle lengths (but could be wrong here). This would give you something closer to the 1/8th of the mask that you were using in your patch (and on larger mask clocksources, we do already cap the interval at 10 minutes - so most really crazy values would be caught for clocksources like the TSC - and maybe we can make this more configurable so we can shorten it as done in your patch to try to debug things).

I've also got a capping patch that I'm testing that keeps time reads from passing that interval. The only thing I'm really cautious about with that change is that we have to make sure the hrtimer that triggers update_wall_clock is always set to expire within that cap (I need to review it again) or else we'll hang ourselves.

thanks
-john

Again, the 50% margin is only on the multiplication overflow. Not on the mask.

So it won't do anything at all for the case we actually care about, namely a broken HPET, afaik.

I'd much rather limit to 50% of the mask too.

Also, why do we actually play games with ilog2 for that overflow calculation? It seems pointless. This is for the setup code, doing a real division there would seem to be a whole lot more straightforward, and not need that big comment. And there's no performance issue. Am I missing something?

Yeah, that thing is fragile. And quite possibly part of the problem.

Linus

Right, but we calculate the mult value based on the mask (or 10 mins, whichever is shorter).

So then when we go back and calculate the max_cycles/max_idle_ns using the mult, we end up with a value smaller then the mask. So the scheduler shouldn't push idle times out beyond that and the debug logic in my patch should be able to catch strangely large values.

Yea, the case my code doesn't catch that yours did is for slightly broken clocksources (I'm thinking two cpus which virtual hpets embedded in them that are slightly off) where you could get negative deltas right after the update. In that case the capping on read is really needed since by the next update the stale value has grown large enough to look like a reasonable offset. The TSC has a similar issue, but its easier to check for negative values because it won't reasonably ever overflow.

Ok, I'll try to rework the code to make this choice and make it more explicitly clear.

I feel like there was a time when this may have been called by some of the clocksource code if it they changed frequency (I think over suspend/resume), but I'm not seeing it in the current source. So yea, likely something to simplify.

"Time is a flat circle..." and thus unfortunately requires some circular logic. :)

thanks
-john

(Warning: I'm replying with my vacation goggles on)

A few thoughts from quickly looking at the patch (some of this is repeating your comments here):

* So 1/8th of the interval seems way too short, as there's clocksources like the ACP PM, which wrap every 2.5 seconds or so. And even with more reasonable clocksource wrapping intervals, the tick scheduler may not schedule the next tick till after that time, which could cause major problems (we don't want the hrtimer expiration calculation to get capped out here, since the timer may be scheduled past 1/8th of the interval, which would keep us from ever accumulating time and clearing the cycle_error added here)

* I suspect something closer to the clocksource_max_deferment() value (which I think is max interval before multiplication overflows could happen - ~12%) which we use in the scheduler would make more sense. Especially since the timer scheduler uses that to calculate how long we can idle for.

* Nulling out delta in timekeeping_get_ns() seems like it could cause problems since time would then possibly go backwards compared to previous reads (as you mentioned, resulting in smaller time jumps). Instead it would probably make more sense to cap the delta at the maximum value (though this assumes the clock doesn't jump back in the interval before the next call to update_wall_time).

* Also, as you note, this would just cause the big time jump to only happen at the next update, since there's no logic in update_wall_time() to limit the jump. I'm not sure if "believing" the large jump at write time make that much more sense, though.

* Finally, you're writing to error while only holding a read lock, but that's sort of a minor thing.

I do agree something that is more helpful in validating the timekeeping here would be nice to avoid further geese chases in the future.

Some possible ideas:
* Checking the accumulation interval isn't beyond the clocksource_max_deferment() value seems like a very good check to have in update_wall_time().

* Maybe when we schedule the next timekeeping update, the tick scheduler could store the expected time for that to fire, and then we could validate that we're relatively close after that value when we do accumulate time (warning if we're running too early or far too late - though with virtualziation, defining a "reasonable" late value is difficult).

* This "expected next tick" time could be used to try to cap read-time intervals in a similar fashion as done here. (Of course, again, we'd have to be careful, since if that expected next tick ends up somehow being before the actual hrtimer expiration value, we could end up stopping time - and the system).

I can try to add some of this when I'm back from holiday in the new year.

Maybe Thomas will have some other ideas?

thanks
-john

Ugh. At the same time, 1/8th of a range is actually bigger than I'd like, since if there is some timer corruption, it means that we only catch it when it's in really big.

But as I said, I'd actually prefer it to be time-based, because it would be good if this approach worked on things like the TSC which is a 64-bit counter..

So yes, that capping was very much arbitrary, and was mostly a case of "this works with the one timer source that I can easily trigger"

I'd rather not be anywhere *close* to any overflow problems. Even for the scheduler all-idle case, I'd argue that there is rather quickly diminishing returns. Yes, a thousand timer interrupts per second are expensive and a noticeable power draw. The difference between "one timer interrupt every two seconds" and "every 20 seconds" is rather less noticeable.

Of course, reasonable clock sources have *much* longer periods than a second (yeah, the acpi pm timer really isn't a good one), so there are probably good middle grounds, The 1/8th was a hack, and one that was aware of teh 300s cycle of the HPET at that..

So part of the nulling was that it was simpler, and part of it was that I expected to get backwards jumps (see the other email to Dave about the inherent races). And with the whole timer mask modulo arithmetic, those backwards jumps just look like biggish positive numbers, not even negative. So it ends up being things like "is it an unsigned number larger than half the mask? Consider it negative" etc.

The "zero it out" was simple, and it worked for my test-case, which was "ok, my machine no longer locks up when I mess with the timer".

And I didn't post the earlier versions of that patch that didn't even *boot*.

I started out trying to do it at a higher level (not on a clock read level, but outside the whole 'convert-to-ns and do the sequence value check'), but during bootup we play a lot of games with initializing the timer sources etc.

So that explains the approach of doing it at that

   cycle_now = tkr->read(tkr->clock);

level, and keeping it very low-level.

But as I already explained in the email that crossed, that low-level thing also results in some fundamental races.

So I considered just capping it there (to a single interval or something). Again, just ignoring - like the read side does - it would have been easier, but at the same time I *really* wanted to make time go forward, so just taking the big value seemed safest.

But yes. this was very much a RFC patch. It's not even ready for real use, as DaveJ found out (although it might be good enough in practice, despite its flaws)

It's not a minor thing, but the alternatives looked worse.

I really wanted to make it per-cpu, and do this with interrupts disabled or something. But that then pushes a big problem to the write time to go over all cpu's and see if there are errors.

So it's not right. But .. It's a hacky patch to get discussion started, and it's actually hard to do "right" when this code has to be basically lockless.

Sounds like a good idea. Also, quite frankly, reading all the code I wasn't ever really able to figure out that things don't overflow. The overflow protection is a bit ad-hoc (that maxshift thing in update_wall_time() really makes baby Jesus cry, despite the season, and it wasn't at all obvious that ntp_tick_length() is fundamentally bigger than xtime_interval, for example).

It's also not clear that the complicated and frankly not-very-obvious shift-loop is any faster than just using a divide - possibly with the "single interval" case being a special case to avoid dividing then.

I was a bit nervous that the whole update of tkr.cycle_last in there could just overrun the actual *read* value of 'tk->tkr.clock'. With the whole offset logic split between update_wall_time() and logarithmic_accumulation(), the code isn't exactly self-explanatory.

Heh.

In general, it would be really nice to know what the expected limits are. It was hard to impossible to figure out the interaction between the timer subsystem and the scheduler tick. It's pretty incestuous, and if there's an explanation for it, I missed it.

I don't think you can cap them to exactly the expected value anyway, since the wall time update *will* get delayed by locking and just interrupts being off etc. And virtual environments will obviously make it much worse. So the capping needs to be somewhat loose anyway.

The patch I posted was actually sloppy by design, exactly because I had so much trouble with trying to be strict. My first patch was a percpu thing that just limited ktime_get() from ever going backwards on that particular cpu (really simple, real;ly stupid), and it got *nowhere*.

Linus

I of course very much like the idea of the timekeeping system doing a bit of self-checking. ;-)

Can we simplify things by just not doing self-checking on clocks that overflow in less than a few minutes? In other words, if someone reports oddball RCU CPU stall warnings when using the ACPI PM timer, am I within my rights to tell them to reproduce the stall using a better timer?

If so, we could possibly get away with the assumption that preemptions don't last longer than the soft-lockup interval, which is currently a bit over 20 seconds (hence "a few minutes" above). And yes, you might avoid a soft lockup by having a series of 15-second preemptions between each pair of instructions, but my response would be to increase my "a few minutes" a bit and to invoke probabilities.

I don't claim to understand the timer code for all the reasons that Linus calls out below, but I believe that this simplifying assumption would in turn simplify the self-check code.

Thanx, Paul

Right.

Not that I'm aware of.

That should be simple enough to implement.

Thanks,

tglx

I think we're also adding more and more debugging. It's definitely a good thing, but I think a lot of them are expected to stay off until you're trying to track down a specific problem. I do always run with CONFIG_DEBUG_PAGEALLOC here and lock debugging/lockdep, and aside from being slow haven't hit trouble.

I know it's 3.16 instead of 3.17, but 16K stacks are probably increasing the pressure on everything in these runs. It's my favorite kernel feature this year, but it's likely to make trinity hurt more on memory constrained boxes.

Your trace with hrtimer debugging yesterday made some sense, but it still should have been survivable. I mean you should have kept seeing lockups from that one poor task being starved out of filling up his pool. I know you have traces with a ton more output, but I'm still wondering if usb-serial and printk from NMI really get along well. I'd try with debugging back on and serial consoles off. We carry patches to make oom print less, just because the time spent on our slow emulated serial console is enough to back the box up into a death spiral.

The fairness of spinlock debugging is a really great point too, definitely worth trying with that off (and fixing, I love spinlock debugging).

-chris

I think in the new year I'll hack up something I run on each kernel build that picks a random subset of the debug options. It's been on my whiteboard for a while anyway, to try and get more 'real world' looking kernel testing. If I can get enough machines to test on, it should still mean we get enough testing that we'll catch stuff early on.

It does seem like things have gotten so 'heavy' that a lot of what I've been seeing have been ghosts. That said, there's also been several real problems that have been shaken out during this thread over the last two months, so I don't feel like we've wasted our time entirely.

That's actually a good point. Even just the forking/exiting overhead is now much higher when we're starting & tearing down hundreds of child processes every few seconds. Couple that with some children 'stuck' in VM functions, and I could see the kernel struggling to find order 2 pages for a while. (Though never to the point where it fails).

So I'm running out of time on this, and will realistically only have this machine over the weekend. I can give that a try, hopefully if it fails, it'll fail early so we can try something else.

Dave

Good call.

I agree - fill_pool() seems to be just plain nasty.

We've had this bug before, btw - a *loong* time ago in the original kmalloc stuff. You really should not fill a pool of memory that way. It's fundamentally wrong to fill a pool and then (later - after having released and re-aqcuired the lock) allocate from the pool. Somebody else will steal the allocations you did, and take advantage of your work.

The high/low watermarks are done completely wrong for that thing too - if things fall below a minimum level, you want to try to make sure it grows clearly past the minimum, so that you don't get stuck just around the minimum. But you need to spread out the pain, rather than make one unlucky allocator have to do all the work.

I'm not sure it was my patch. I'm wondering if it's because Dave still has preemption off, and the backtraces look different (and better) as a result.

But yes, trying with DEBUG_OBJECTS off might be a good idea. It's entirely possible that the debug code is actually triggering bugs of its own, rather than showing other peoples bugs.

Linus

Err, maybe a wild guess, but could XSAVE be encountering some problems, like store ordering violations or somesuch?

Quick search shows

"AZ72. Store Ordering Violation When Using XSAVE"

here http://download.intel.com/design/mobile/specupdt/320121.pdf which talks about SSE context stores happening out of order. Now, there are a lot of IFs like does Dave's machine even have the erratum and even if, would that erratum cause some sort of a livelock leading to the kernel lockups and so on and so on...

It might be worth to rule out though.

Regards/Gruss,
    Boris.

Sent from a fat crate under my desk. Formatting is fine.
--

I admit that my understanding of the disaster that is x86's FPU handling is limited, but I'm moderately confident that save_xstate_sig is broken.

The code is:

	if (user_has_fpu()) {
		/* Save the live register state to the user directly. */
		if (save_user_xstate(buf_fx))
			return -1;
		/* Update the thread's fxstate to save the fsave header. */
		if (ia32_fxstate)
			fpu_fxsave(&tsk->thread.fpu);
	} else {
		sanitize_i387_state(tsk);
		if (__copy_to_user(buf_fx, xsave, xstate_size))
			return -1;
	}

Suppose that user_has_fpu() returns true, we call save_user_xstate, and the xsave instruction (or anything else in there, for that matter) causes a page fault.

The page fault handler is well within its rights to schedule. At that point, *we might not own the FPU any more*, depending on the vagaries of eager vs lazy mode. So, when we schedule back in and resume from the page fault, we are in the wrong branch of the if statement.

At this point, we're going to write garbage (possibly sensitive garbage) to the userspace signal frame. I don't see why this would cause an infinite loop, but I don't think it's healthy.

FWIW, if xsave traps with cr2 value, then there would indeed be an infinite loop in here. It seems to work right on my machine. Dave, want to run the attached little test?

--Andy

#define _GNU_SOURCE
#include <err.h>
#include <stdio.h>
#include <string.h>
#include <stdlib.h>
#include <sys/mman.h>
#include <sys/ucontext.h>

static volatile unsigned char *buf, *xsave_addr;
static volatile int nfailures = 0;

static void sethandler(int sig, void (*handler)(int, siginfo_t *, void *),
int flags)

{
	struct sigaction sa;
	memset(&sa, 0, sizeof(sa));
	sa.sa_sigaction = handler;
	sa.sa_flags = SA_SIGINFO | flags;
	sigemptyset(&sa.sa_mask);
	if (sigaction(sig, &sa, 0))
		err(1, "sigaction");
}

static void clearhandler(int sig)

{
	struct sigaction sa;
	memset(&sa, 0, sizeof(sa));
	sa.sa_handler = SIG_DFL;
	sigemptyset(&sa.sa_mask);
	if (sigaction(sig, &sa, 0))
		err(1, "sigaction");
}

static void sigsegv(int sig, siginfo_t *si, void *ctx_void)

{
	ucontext_t *ctx = (ucontext_t*)ctx_void;

	unsigned long cr2 = (unsigned long)ctx->uc_mcontext.gregs[REG_CR2];
	unsigned long start = (unsigned long)buf;

	extern unsigned char xsave_insn[], after_xsave_insn[];
	
	if (ctx->uc_mcontext.gregs[REG_RIP] != (unsigned long)xsave_insn) {
		printf("Uncorrectable segfault\n");
		clearhandler(SIGSEGV);
		return;
	}

	if (si->si_code != SEGV_ACCERR) {
		printf("Segfault was %d (trap %d), not SEGV_ACCERR\n",
		       si->si_code, ctx->uc_mcontext.gregs[REG_TRAPNO]);
		clearhandler(SIGSEGV);
		return;
	}

	if (cr2 != (unsigned long)si->si_addr) {
		printf("CR2 (0x%lx) != si_addr (0x%lx)\n",
		       cr2, (unsigned long)si->si_addr);
		clearhandler(SIGSEGV);
		return;
	}

	if (cr2 >= start && cr2 <= (start + 4095)) {
		printf("[OK]\txsave offset = %d, cr2 offset = %d\n",
		       (int)(xsave_addr - buf), (int)(cr2 - start));
	} else if (cr2 >= start + 4096 && cr2 <= start + 8191) {
		printf("[FAIL]\txsave offset = %d, cr2 offset = %d\n",
		       (int)(xsave_addr - buf), (int)(cr2 - start));

		nfailures++;
	} else if (cr2 >= start + 8192 && cr2 <= start + 12287) {
		printf("[OK]\txsave offset = %d, cr2 offset = %d\n",
		       (int)(xsave_addr - buf), (int)(cr2 - start));
	} else {
		printf("[FAIL]\tcr2 is completely out of range\n");
		abort();
	}

	ctx->uc_mcontext.gregs[REG_RIP] = (unsigned long)after_xsave_insn;
}

int main()

{
	int i;

	buf = mmap(NULL, 4096*3, PROT_NONE,
		   MAP_PRIVATE | MAP_ANONYMOUS | MAP_NORESERVE, -1, 0);
	if (buf == MAP_FAILED)
		err(1, "mmap");

	if (mmap((unsigned char *)buf + 4096, 4096, PROT_READ | PROT_WRITE,
		 MAP_PRIVATE | MAP_ANONYMOUS | MAP_FIXED, -1, 0) == MAP_FAILED)
		err(1, "mmap");

	sethandler(SIGSEGV, sigsegv, 0);

	for (i = 0; i < 8193; i += 64) {
		xsave_addr = buf + i;
		printf("XSAVE to offset %d\n", i);
		asm volatile ("xsave_insn: xsaveq %0 ; after_xsave_insn:"
			      : "=m" (*xsave_addr)
			      : "a" (0xffffffff), "d" (0xffffffff));
	}

	if (nfailures)
		printf("%d failures\n", nfailures);
	else
		printf("PASS!\n");

	return 0;
}

Very possible. The FPU code *is* nasty.

You don't even have to page fault. Preemption..

But that shouldn't actually be the bug. This is just an optimization. If we have the FPU, we save it from the FP state, rather than copying it from our kernel copy. If we schedule (page fault, preemption, whatever) and lose the FPU, the code still works - we'll just take a TS fault, and have to reload the information.

So I'm with you in that there can certainly be bugs in the FPU handling, but I don't think this is one.

Linus

Not if this happens:

    /*
     * Paranoid restore. send a SIGSEGV if we fail to restore the state.
     */
    if (unlikely(restore_fpu_checking(tsk))) {
        drop_init_fpu(tsk);
        force_sig_info(SIGSEGV, SEND_SIG_PRIV, tsk);
        return;
    }

I have no idea what, if anything, can cause FPU restore to fail, but that looks like an infinite loop to me.

And the fact that we have an xsave instruction that can cause page faults *and* has an extable fixup doesn't exactly inspire confidence, but the code looks correct.

If this is easy enough for Dave to trigger, it could be worth instrumenting __do_page_fault to log when a fault happens on that xsave instruction and to maybe also log the outcome. Do we know whether your fault retry fixes solved the problem yet?

FWIW, Dave's run of my test seems to rule out easy bugs in his CPU, and I couldn't trigger a bogus cr2 value on Sandy Bridge or Core 2 Quad.

--Andy

Andy Lutomirski
AMA Capital Management, LLC

XSAVE to offset 0
[OK] xsave offset = 0, cr2 offset = 831
XSAVE to offset 64
[OK] xsave offset = 64, cr2 offset = 895
XSAVE to offset 128
[OK] xsave offset = 128, cr2 offset = 959
XSAVE to offset 192
[OK] xsave offset = 192, cr2 offset = 1023
XSAVE to offset 256
[OK] xsave offset = 256, cr2 offset = 1087
XSAVE to offset 320
[OK] xsave offset = 320, cr2 offset = 1151
XSAVE to offset 384
[OK] xsave offset = 384, cr2 offset = 1215
XSAVE to offset 448
[OK] xsave offset = 448, cr2 offset = 1279
XSAVE to offset 512
[OK] xsave offset = 512, cr2 offset = 1343
XSAVE to offset 576
[OK] xsave offset = 576, cr2 offset = 1407
XSAVE to offset 640
[OK] xsave offset = 640, cr2 offset = 1471
XSAVE to offset 704
[OK] xsave offset = 704, cr2 offset = 1535
XSAVE to offset 768
[OK] xsave offset = 768, cr2 offset = 1599
XSAVE to offset 832
[OK] xsave offset = 832, cr2 offset = 1663
XSAVE to offset 896
[OK] xsave offset = 896, cr2 offset = 1727
XSAVE to offset 960
[OK] xsave offset = 960, cr2 offset = 1791
XSAVE to offset 1024
[OK] xsave offset = 1024, cr2 offset = 1855
XSAVE to offset 1088
[OK] xsave offset = 1088, cr2 offset = 1919
XSAVE to offset 1152
[OK] xsave offset = 1152, cr2 offset = 1983
XSAVE to offset 1216
[OK] xsave offset = 1216, cr2 offset = 2047
XSAVE to offset 1280
[OK] xsave offset = 1280, cr2 offset = 2111
XSAVE to offset 1344
[OK] xsave offset = 1344, cr2 offset = 2175
XSAVE to offset 1408
[OK] xsave offset = 1408, cr2 offset = 2239
XSAVE to offset 1472
[OK] xsave offset = 1472, cr2 offset = 2303
XSAVE to offset 1536
[OK] xsave offset = 1536, cr2 offset = 2367
XSAVE to offset 1600
[OK] xsave offset = 1600, cr2 offset = 2431
XSAVE to offset 1664
[OK] xsave offset = 1664, cr2 offset = 2495
XSAVE to offset 1728
[OK] xsave offset = 1728, cr2 offset = 2559
XSAVE to offset 1792
[OK] xsave offset = 1792, cr2 offset = 2623
XSAVE to offset 1856
[OK] xsave offset = 1856, cr2 offset = 2687
XSAVE to offset 1920
[OK] xsave offset = 1920, cr2 offset = 2751
XSAVE to offset 1984
[OK] xsave offset = 1984, cr2 offset = 2815
XSAVE to offset 2048
[OK] xsave offset = 2048, cr2 offset = 2879
XSAVE to offset 2112
[OK] xsave offset = 2112, cr2 offset = 2943
XSAVE to offset 2176
[OK] xsave offset = 2176, cr2 offset = 3007
XSAVE to offset 2240
[OK] xsave offset = 2240, cr2 offset = 3071
XSAVE to offset 2304
[OK] xsave offset = 2304, cr2 offset = 3135
XSAVE to offset 2368
[OK] xsave offset = 2368, cr2 offset = 3199
XSAVE to offset 2432
[OK] xsave offset = 2432, cr2 offset = 3263
XSAVE to offset 2496
[OK] xsave offset = 2496, cr2 offset = 3327
XSAVE to offset 2560
[OK] xsave offset = 2560, cr2 offset = 3391
XSAVE to offset 2624
[OK] xsave offset = 2624, cr2 offset = 3455
XSAVE to offset 2688
[OK] xsave offset = 2688, cr2 offset = 3519
XSAVE to offset 2752
[OK] xsave offset = 2752, cr2 offset = 3583
XSAVE to offset 2816
[OK] xsave offset = 2816, cr2 offset = 3647
XSAVE to offset 2880
[OK] xsave offset = 2880, cr2 offset = 3711
XSAVE to offset 2944
[OK] xsave offset = 2944, cr2 offset = 3775
XSAVE to offset 3008
[OK] xsave offset = 3008, cr2 offset = 3839
XSAVE to offset 3072
[OK] xsave offset = 3072, cr2 offset = 3903
XSAVE to offset 3136
[OK] xsave offset = 3136, cr2 offset = 3967
XSAVE to offset 3200
[OK] xsave offset = 3200, cr2 offset = 4031
XSAVE to offset 3264
[OK] xsave offset = 3264, cr2 offset = 4095
XSAVE to offset 3328
[OK] xsave offset = 3328, cr2 offset = 3328
XSAVE to offset 3392
[OK] xsave offset = 3392, cr2 offset = 3392
XSAVE to offset 3456
[OK] xsave offset = 3456, cr2 offset = 3456
XSAVE to offset 3520
[OK] xsave offset = 3520, cr2 offset = 3520
XSAVE to offset 3584
[OK] xsave offset = 3584, cr2 offset = 3584
XSAVE to offset 3648
[OK] xsave offset = 3648, cr2 offset = 3648
XSAVE to offset 3712
[OK] xsave offset = 3712, cr2 offset = 3712
XSAVE to offset 3776
[OK] xsave offset = 3776, cr2 offset = 3776
XSAVE to offset 3840
[OK] xsave offset = 3840, cr2 offset = 3840
XSAVE to offset 3904
[OK] xsave offset = 3904, cr2 offset = 3904
XSAVE to offset 3968
[OK] xsave offset = 3968, cr2 offset = 3968
XSAVE to offset 4032
[OK] xsave offset = 4032, cr2 offset = 4032
XSAVE to offset 4096
XSAVE to offset 4160
XSAVE to offset 4224
XSAVE to offset 4288
XSAVE to offset 4352
XSAVE to offset 4416
XSAVE to offset 4480
XSAVE to offset 4544
XSAVE to offset 4608
XSAVE to offset 4672
XSAVE to offset 4736
XSAVE to offset 4800
XSAVE to offset 4864
XSAVE to offset 4928
XSAVE to offset 4992
XSAVE to offset 5056
XSAVE to offset 5120
XSAVE to offset 5184
XSAVE to offset 5248
XSAVE to offset 5312
XSAVE to offset 5376
XSAVE to offset 5440
XSAVE to offset 5504
XSAVE to offset 5568
XSAVE to offset 5632
XSAVE to offset 5696
XSAVE to offset 5760
XSAVE to offset 5824
XSAVE to offset 5888
XSAVE to offset 5952
XSAVE to offset 6016
XSAVE to offset 6080
XSAVE to offset 6144
XSAVE to offset 6208
XSAVE to offset 6272
XSAVE to offset 6336
XSAVE to offset 6400
XSAVE to offset 6464
XSAVE to offset 6528
XSAVE to offset 6592
XSAVE to offset 6656
XSAVE to offset 6720
XSAVE to offset 6784
XSAVE to offset 6848
XSAVE to offset 6912
XSAVE to offset 6976
XSAVE to offset 7040
XSAVE to offset 7104
XSAVE to offset 7168
XSAVE to offset 7232
XSAVE to offset 7296
XSAVE to offset 7360
XSAVE to offset 7424
[OK] xsave offset = 7424, cr2 offset = 8255
XSAVE to offset 7488
[OK] xsave offset = 7488, cr2 offset = 8319
XSAVE to offset 7552
[OK] xsave offset = 7552, cr2 offset = 8383
XSAVE to offset 7616
[OK] xsave offset = 7616, cr2 offset = 8447
XSAVE to offset 7680
[OK] xsave offset = 7680, cr2 offset = 8511
XSAVE to offset 7744
[OK] xsave offset = 7744, cr2 offset = 8575
XSAVE to offset 7808
[OK] xsave offset = 7808, cr2 offset = 8639
XSAVE to offset 7872
[OK] xsave offset = 7872, cr2 offset = 8703
XSAVE to offset 7936
[OK] xsave offset = 7936, cr2 offset = 8767
XSAVE to offset 8000
[OK] xsave offset = 8000, cr2 offset = 8831
XSAVE to offset 8064
[OK] xsave offset = 8064, cr2 offset = 8895
XSAVE to offset 8128
[OK] xsave offset = 8128, cr2 offset = 8959
XSAVE to offset 8192
[OK] xsave offset = 8192, cr2 offset = 9023
PASS!

Finally back in front of that machine.

Here's save_xstate_sig:

ve_xstate_sig>:

ffffffff8100f370:       e8 0b 2b 7c 00          callq  ffffffff817d1e80 <__fentry__>
ffffffff8100f375:       55                      push   %rbp
ffffffff8100f376:       48 63 d2                movslq %edx,%rdx
ffffffff8100f379:       48 89 e5                mov    %rsp,%rbp
ffffffff8100f37c:       41 57                   push   %r15
ffffffff8100f37e:       41 56                   push   %r14
ffffffff8100f380:       45 31 f6                xor    %r14d,%r14d
ffffffff8100f383:       41 55                   push   %r13
ffffffff8100f385:       41 54                   push   %r12
ffffffff8100f387:       49 89 fc                mov    %rdi,%r12
ffffffff8100f38a:       53                      push   %rbx
ffffffff8100f38b:       48 89 f3                mov    %rsi,%rbx
ffffffff8100f38e:       48 83 ec 18             sub    $0x18,%rsp
ffffffff8100f392:       65 4c 8b 2c 25 00 aa    mov    %gs:0xaa00,%r13
ffffffff8100f399:       00 00 
ffffffff8100f39b:       48 39 f7                cmp    %rsi,%rdi
ffffffff8100f39e:       4d 8b bd 98 05 00 00    mov    0x598(%r13),%r15
ffffffff8100f3a5:       41 0f 95 c6             setne  %r14b
ffffffff8100f3a9:       65 48 8b 04 25 08 aa    mov    %gs:0xaa08,%rax
ffffffff8100f3b0:       00 00 
ffffffff8100f3b2:       48 01 fa                add    %rdi,%rdx
ffffffff8100f3b5:       48 8b 88 48 c0 ff ff    mov    -0x3fb8(%rax),%rcx
ffffffff8100f3bc:       b8 f3 ff ff ff          mov    $0xfffffff3,%eax
ffffffff8100f3c1:       0f 82 00 01 00 00       jb     ffffffff8100f4c7 <save_xstate_sig+0x157>
ffffffff8100f3c7:       48 39 d1                cmp    %rdx,%rcx
ffffffff8100f3ca:       0f 82 f7 00 00 00       jb     ffffffff8100f4c7 <save_xstate_sig+0x157>
ffffffff8100f3d0:       41 8b 85 94 05 00 00    mov    0x594(%r13),%eax
ffffffff8100f3d7:       85 c0                   test   %eax,%eax
ffffffff8100f3d9:       74 3d                   je     ffffffff8100f418 <save_xstate_sig+0xa8>
ffffffff8100f3db:       e9 00 01 00 00          jmpq   ffffffff8100f4e0 <save_xstate_sig+0x170>
ffffffff8100f3e0:       48 8d bb 00 02 00 00    lea    0x200(%rbx),%rdi
ffffffff8100f3e7:       be 40 00 00 00          mov    $0x40,%esi
ffffffff8100f3ec:       e8 3f 5e 36 00          callq  ffffffff81375230 <__clear_user>
ffffffff8100f3f1:       85 c0                   test   %eax,%eax
ffffffff8100f3f3:       0f 85 81 01 00 00       jne    ffffffff8100f57a <save_xstate_sig+0x20a>
ffffffff8100f3f9:       ba ff ff ff ff          mov    $0xffffffff,%edx
ffffffff8100f3fe:       89 c1                   mov    %eax,%ecx
ffffffff8100f400:       48 89 df                mov    %rbx,%rdi
ffffffff8100f403:       89 d0                   mov    %edx,%eax
ffffffff8100f405:       0f 1f 00                nopl   (%rax)
ffffffff8100f408:       48 0f ae 27             xsave64 (%rdi)
ffffffff8100f40c:       0f 1f 00                nopl   (%rax)
ffffffff8100f40f:       e9 ea 00 00 00          jmpq   ffffffff8100f4fe <save_xstate_sig+0x18e>
ffffffff8100f414:       0f 1f 40 00             nopl   0x0(%rax)
ffffffff8100f418:       e9 33 01 00 00          jmpq   ffffffff8100f550 <save_xstate_sig+0x1e0>
ffffffff8100f41d:       4c 89 ef                mov    %r13,%rdi
ffffffff8100f420:       e8 1b fe ff ff          callq  ffffffff8100f240 <__sanitize_i387_state>
ffffffff8100f425:       8b 05 95 d5 0b 01       mov    0x10bd595(%rip),%eax        # ffffffff820cc9c0 <xstate_size>
ffffffff8100f42b:       89 45 cc                mov    %eax,-0x34(%rbp)
ffffffff8100f42e:       e8 7d 33 19 00          callq  ffffffff811a27b0 <might_fault>
ffffffff8100f433:       48 89 df                mov    %rbx,%rdi
ffffffff8100f436:       4c 89 fe                mov    %r15,%rsi
ffffffff8100f439:       8b 55 cc                mov    -0x34(%rbp),%edx
ffffffff8100f43c:       e8 2f 44 36 00          callq  ffffffff81373870 <copy_user_generic_unrolled>
ffffffff8100f441:       85 c0                   test   %eax,%eax
ffffffff8100f443:       0f 85 27 01 00 00       jne    ffffffff8100f570 <save_xstate_sig+0x200>
ffffffff8100f449:       45 85 f6                test   %r14d,%r14d
ffffffff8100f44c:       0f 85 c4 00 00 00       jne    ffffffff8100f516 <save_xstate_sig+0x1a6>
ffffffff8100f452:       49 c7 c4 60 cd 0c 82    mov    $0xffffffff820ccd60,%r12
ffffffff8100f459:       e8 52 33 19 00          callq  ffffffff811a27b0 <might_fault>
ffffffff8100f45e:       48 8d bb d0 01 00 00    lea    0x1d0(%rbx),%rdi
ffffffff8100f465:       4c 89 e6                mov    %r12,%rsi
ffffffff8100f468:       ba 30 00 00 00          mov    $0x30,%edx
ffffffff8100f46d:       e8 fe 43 36 00          callq  ffffffff81373870 <copy_user_generic_unrolled>
ffffffff8100f472:       41 89 c5                mov    %eax,%r13d
ffffffff8100f475:       41 89 c4                mov    %eax,%r12d
ffffffff8100f478:       e9 bb 00 00 00          jmpq   ffffffff8100f538 <save_xstate_sig+0x1c8>
ffffffff8100f47d:       31 d2                   xor    %edx,%edx
ffffffff8100f47f:       8b 05 3b d5 0b 01       mov    0x10bd53b(%rip),%eax        # ffffffff820cc9c0 <xstate_size>
ffffffff8100f485:       41 89 d4                mov    %edx,%r12d
ffffffff8100f488:       0f 1f 00                nopl   (%rax)
ffffffff8100f48b:       c7 04 03 45 58 50 46    movl   $0x46505845,(%rbx,%rax,1)
ffffffff8100f492:       0f 1f 00                nopl   (%rax)
ffffffff8100f495:       89 d0                   mov    %edx,%eax
ffffffff8100f497:       0f 1f 00                nopl   (%rax)
ffffffff8100f49a:       8b 8b 00 02 00 00       mov    0x200(%rbx),%ecx
ffffffff8100f4a0:       0f 1f 00                nopl   (%rax)
ffffffff8100f4a3:       41 09 c4                or     %eax,%r12d
ffffffff8100f4a6:       83 c9 03                or     $0x3,%ecx
ffffffff8100f4a9:       89 d0                   mov    %edx,%eax
ffffffff8100f4ab:       45 09 ec                or     %r13d,%r12d
ffffffff8100f4ae:       0f 1f 00                nopl   (%rax)
ffffffff8100f4b1:       89 8b 00 02 00 00       mov    %ecx,0x200(%rbx)
ffffffff8100f4b7:       0f 1f 00                nopl   (%rax)
ffffffff8100f4ba:       41 09 c4                or     %eax,%r12d
ffffffff8100f4bd:       31 c0                   xor    %eax,%eax
ffffffff8100f4bf:       45 85 e4                test   %r12d,%r12d
ffffffff8100f4c2:       0f 95 c0                setne  %al
ffffffff8100f4c5:       f7 d8                   neg    %eax
ffffffff8100f4c7:       48 83 c4 18             add    $0x18,%rsp
ffffffff8100f4cb:       5b                      pop    %rbx
ffffffff8100f4cc:       41 5c                   pop    %r12
ffffffff8100f4ce:       41 5d                   pop    %r13
ffffffff8100f4d0:       41 5e                   pop    %r14
ffffffff8100f4d2:       41 5f                   pop    %r15
ffffffff8100f4d4:       5d                      pop    %rbp
ffffffff8100f4d5:       c3                      retq   

and __clear_user :

ffffffff81375230 <__clear_user>:

ffffffff81375230:       e8 4b cc 45 00          callq  ffffffff817d1e80 <__fentry__>
ffffffff81375235:       55                      push   %rbp
ffffffff81375236:       48 89 e5                mov    %rsp,%rbp
ffffffff81375239:       41 54                   push   %r12
ffffffff8137523b:       49 89 fc                mov    %rdi,%r12
ffffffff8137523e:       53                      push   %rbx
ffffffff8137523f:       48 89 f3                mov    %rsi,%rbx
ffffffff81375242:       e8 69 d5 e2 ff          callq  ffffffff811a27b0 <might_fault>
ffffffff81375247:       0f 1f 00                nopl   (%rax)
ffffffff8137524a:       48 89 d8                mov    %rbx,%rax
ffffffff8137524d:       48 c1 eb 03             shr    $0x3,%rbx
ffffffff81375251:       4c 89 e7                mov    %r12,%rdi
ffffffff81375254:       83 e0 07                and    $0x7,%eax
ffffffff81375257:       48 89 d9                mov    %rbx,%rcx
ffffffff8137525a:       be 08 00 00 00          mov    $0x8,%esi
ffffffff8137525f:       31 d2                   xor    %edx,%edx
ffffffff81375261:       48 85 c9                test   %rcx,%rcx
ffffffff81375264:       74 0a                   je     ffffffff81375270 <__clear_user+0x40>
ffffffff81375266:       48 89 17                mov    %rdx,(%rdi)
ffffffff81375269:       48 01 f7                add    %rsi,%rdi
ffffffff8137526c:       ff c9                   dec    %ecx
ffffffff8137526e:       75 f6                   jne    ffffffff81375266 <__clear_user+0x36>
ffffffff81375270:       48 89 c1                mov    %rax,%rcx
ffffffff81375273:       85 c9                   test   %ecx,%ecx
ffffffff81375275:       74 09                   je     ffffffff81375280 <__clear_user+0x50>
ffffffff81375277:       88 17                   mov    %dl,(%rdi)
ffffffff81375279:       48 ff c7                inc    %rdi
ffffffff8137527c:       ff c9                   dec    %ecx
ffffffff8137527e:       75 f7                   jne    ffffffff81375277 <__clear_user+0x47>
ffffffff81375280:       0f 1f 00                nopl   (%rax)
ffffffff81375283:       5b                      pop    %rbx
ffffffff81375284:       48 89 c8                mov    %rcx,%rax
ffffffff81375287:       41 5c                   pop    %r12
ffffffff81375289:       5d                      pop    %rbp
ffffffff8137528a:       c3                      retq   
ffffffff8137528b:       0f 1f 44 00 00          nopl   0x0(%rax,%rax,1)

If you need more, I've kept the vmlinux handy. I'm going to try your two patches on top of .18, with the same kernel config, and see where that takes us. Hopefully to happier places.

Dave

Not so much. Died very quickly.

[  270.822490] BUG: unable to handle kernel paging request at 000000000249db90
[  270.822573] IP: [<000000336ef04084>] 0x336ef04084
[  270.822602] PGD 20e5ee067 PUD 20e5ef067 PMD 23126d067 PTE 94ec80
[  270.822633] Oops: 0006 [#1] SMP 
[  270.822652] Modules linked in: hidp llc2 af_key fuse bnep can_raw scsi_transport_iscsi nfnetlink can_bcm rfcomm nfc caif_socket caif af_802154 ieee802154 phonet af_rxrpc bluetooth can pppoe pppox ppp_generic slhc irda crc_ccitt rds rose sctp libcrc32c x25 atm netrom appletalk ipx p8023 psnap p8022 llc ax25 cfg80211 rfkill snd_hda_codec_realtek snd_hda_codec_generic snd_hda_codec_hdmi snd_hda_intel snd_hda_controller snd_hda_codec snd_hwdep snd_seq snd_seq_device snd_pcm coretemp hwmon x86_pkg_temp_thermal kvm_intel snd_timer kvm snd crct10dif_pclmul crc32c_intel ghash_clmulni_intel microcode pcspkr serio_raw usb_debug shpchp e1000e soundcore ptp pps_core nfsd auth_rpcgss oid_registry nfs_acl lockd grace sunrpc
[  270.822979] CPU: 3 PID: 9856 Comm: trinity-c93 Not tainted 3.18.0+ #105
[  270.823042] task: ffff8801a45416d0 ti: ffff88020e72c000 task.ti: ffff88020e72c000
[  270.823067] RIP: 0033:[<000000336ef04084>]  [<000000336ef04084>] 0x336ef04084
[  270.823096] RSP: 002b:00007fff9c3304c0  EFLAGS: 00010202
[  270.823117] RAX: 000000336f1b68c0 RBX: 000000000249db90 RCX: 0000000000000000
[  270.823142] RDX: fffffffffffffffe RSI: 00000000fbad8000 RDI: 00007fff9c3304c0
[  270.823168] RBP: 000000000249db90 R08: 0000000000000000 R09: 0000000000002680
[  270.823192] R10: 000000000000001f R11: 0000000000000246 R12: ffffffffffffffff
[  270.823217] R13: 000000000041edb9 R14: 00007fff9c3305f8 R15: 0000000000000001
[  270.823241] FS:  00007f5fd4acf740(0000) GS:ffff880245400000(0000) knlGS:0000000000000000
[  270.823268] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  270.823288] CR2: 00007f5fd2640113 CR3: 000000020e5ed000 CR4: 00000000001407e0
[  270.823312] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[  270.823336] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[  270.823360] 
[  270.823370] RIP  [<000000336ef04084>] 0x336ef04084
[  270.823392]  RSP <00007fff9c3304c0>
[  270.824407] CR2: 000000000249db90
[  270.825443] ---[ end trace d6eb8dccb8df6213 ]---
[  270.826448] Kernel panic - not syncing: Fatal exception

different flavour of the same thing

[  298.759018] BUG: unable to handle kernel paging request at 00000000016edc30
[  298.759108] IP: [<0000000000412c20>] 0x412c20
[  298.759130] PGD 2315d1067 PUD 2315d2067 PMD 2315d7067 PTE 3c2a880
[  298.759159] Oops: 0004 [#1] SMP 
[  298.759177] Modules linked in: rfcomm hidp bnep llc2 af_key scsi_transport_iscsi nfnetlink can_raw can_bcm nfc caif_socket caif af_802154 ieee802154 phonet af_rxrpc bluetooth can pppoe pppox ppp_generic slhc irda crc_ccitt rds rose sctp libcrc32c x25 atm netrom appletalk ipx p8023 psnap p8022 llc ax25 cfg80211 rfkill coretemp hwmon x86_pkg_temp_thermal kvm_intel kvm crct10dif_pclmul crc32c_intel ghash_clmulni_intel snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_codec_generic microcode serio_raw pcspkr snd_hda_intel snd_hda_controller snd_hda_codec snd_hwdep snd_seq snd_seq_device usb_debug snd_pcm e1000e ptp snd_timer shpchp snd pps_core soundcore nfsd auth_rpcgss oid_registry nfs_acl lockd grace sunrpc
[  298.759487] CPU: 3 PID: 4568 Comm: trinity-c193 Not tainted 3.18.0+ #105
[  298.759550] task: ffff88018c534470 ti: ffff8801deafc000 task.ti: ffff8801deafc000
[  298.759575] RIP: 0033:[<0000000000412c20>]  [<0000000000412c20>] 0x412c20
[  298.759601] RSP: 002b:00007fff8b5d80c0  EFLAGS: 00010202
[  298.759621] RAX: 00000000016edc20 RBX: 00000000017769f0 RCX: 00000000016edc20
[  298.759645] RDX: 0000000000000003 RSI: 0000000000000003 RDI: 000000336f1b76e0
[  298.759668] RBP: 00000000016edc20 R08: 000000336f1b70fc R09: 000000336f1b7140
[  298.759692] R10: 000000000000001f R11: 0000000000000246 R12: 0000000001776ef0
[  298.759716] R13: 00000000017769f0 R14: 0000000000000000 R15: 0000000000000000
[  298.759740] FS:  00007fbc02017740(0000) GS:ffff880245400000(0000) knlGS:0000000000000000
[  298.759766] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  298.760773] CR2: 0000000000000004 CR3: 00000002315d0000 CR4: 00000000001407e0
[  298.761788] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[  298.762802] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000600
[  298.763812] 
[  298.764808] RIP  [<0000000000412c20>] 0x412c20
[  298.765806]  RSP <00007fff8b5d80c0>
[  298.766772] CR2: 00000000016edc30
[  298.767725] ---[ end trace eaa888b859a91308 ]---
[  298.768672] Kernel panic - not syncing: Fatal exception

This seems to be easily reproducable at least..

Dave

Damn, damn, damn. That's because of a stupid typo on the patches. We have these very similar variables ("flags" and "fault") that have very similar fault information, but they are completely different.

The "fault & FAULT_FLAG_USER" test is wrong, it should test "flags & FAULT_FLAG_USER". Patch attached.

The half-way good news is that this certainly confirms that trinity is triggering the "page fault with fatal signal pending" special case.

Linus

 arch/x86/mm/fault.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

index b74a7e130b03..38dcec403b46 100644
@@ -1247,7 +1247,7 @@ good_area:
 		}
 
 		/* User mode? Just return to handle the fatal exception */
-		if (fault & FAULT_FLAG_USER)
+		if (flags & FAULT_FLAG_USER)
 			return;
 
 		/* Not returning to user mode? Handle exceptions or die: */

Yup, that seems to be the only obvious bug in those commits. It's survived for long with that change on top.

Now let's see how long it runs for..

Dave

Ok, that just confirmed that it was the call to __clear_user and the "xsave64" instruction like expected. And the offset in __clear_user() was just the return address after the call to "might_fault", so this all matches with __clear_user and/or the xsave64 instruction taking infinite page-faults.

.. which also kind of matches with your old "pipe/page fault oddness" report, where it was the single-byte write in "fault_in_pages_writable()" that kept taking infinite page faults.

However.

I'm back looking at your old trace for the pipe/page fault oddness report, and it goes like this (simplified):

    __do_page_fault() {
      down_read_trylock();
      __might_sleep();
      find_vma();
      handle_mm_fault() {
        _raw_spin_lock();
        ptep_set_access_flags();
        _raw_spin_unlock();
      }
      up_read();
    }

which is a bit hard to read because it doesn't trace all functions - it only traces the ones that didn't get inlined.

But "didn't get inlined" already means that we know the handle_mm_fault() codepath it didn't go outside of mm/memory.c apart from the quoted parts. So no hugetlb.c code, and no mm/filemap.c code. So there are no lock_page_or_retry() failures, for example.

There are only two ptep_set_access_flags() calls in mm/memory.c - in do_wp_page() for the page re-use case, and in handle_pte_fault() for the "pte was present and already writable".

And it's almost certainly not the do_wp_page() one, because that is not something that gcc inlines at least for me (it has two different call sites).

So I'm a bit less optimistic about the VM_FAULT_RETRY + fatal_signal_pending() scenario, because it simply doesn't match your earlier odd page fault thing.

Your earlier page fault problem really looks like the VM is confused about the page table contents. The kernel thinks the page is already perfectly writable, and just marks it accessed and returns. But the page fault just kept happening. And from that thread, you had "error-code=0", which means "not present page, write fault".

So that earlier "infinite page fault" bug really smells like something else went wrong. One of:

- we're using the wrong "mm". The x86 fault code uses "tsk->mm",
rather than "tsk->active_mm", which is somewhat dubious. At the same time, they should always match, unless "mm" is NULL. And we know mm isn't NULL, because __do_page_fault checks for that lack of user context..

There's also small areas in the scheduler where the current task
itself is kind of a gray area, and the CPU hasn't been switched to the new cr3 yet, but those are all irq-off. They don't match your stack trace anyway.

- we walk the page table directories without necessarily checking
that they are writable. So maybe the PTE itself is writable, but the PMD isn't. We do have read-only PMD's (see pmd_wrprotect). But that *should* only trigger for hugepage entries. And again, your old error code really said that the CPU thinks it is "not present".

- the whole NUMA protnone mess. That's what I suspected back then,
and I keep coming back to it. That's the code that makes the kernel think that "pte_present is set", even though the CPU sees that the actual PTE_PRESENT bit is clear.

Ugh. I'd have loved for the VM_FAULT_RETRY thing to explain all your problems, but it doesn't.

Linus

Sort of in the FWIW category, may not mean a thing.

I did find something in 3.16.0 that is troubling me at times, causing a very busy quad core Phenom. But I have located the culprit in my case.

Look at your Xorg.0.log. Because the nouveau bits in the 3.16.0 kernel I'm using are no longer 100% compatible with an Xorg install thats now 5 years old, I am generating Xorg.0.logs that can reach 500 megabyte or more in a couple weeks. I am trying to run down the latest Xorg I can build here on this *buntu 10.04.4 LTS box, but haven't located a URL to get the tarball from. Yet, its been busy here.

Cheers, Gene Heskett

"There are four boxes to be used in defense of liberty:
 soap, ballot, jury, and ammo. Please use in that order."
-Ed Howdershelt (Author)
Genes Web page <http://geneslinuxbox.net:6309/gene>
US V Castleman, SCOTUS, Mar 2014 is grounds for Impeaching SCOTUS

Yeah, it was intentional. Least lines.

Peterz was looking at corner case proofing the thing. Saving those cycles has been entirely too annoying.

https://lkml.org/lkml/2014/4/8/295

-Mike

Hm, so that discussion died with:

https://lkml.org/lkml/2014/4/8/343

Did you ever get around to trying Peter's patch?

But ... I've yet to see rq_clock problems cause actual lockups. That's the main problem we have with its (un)robustness and why Peter created that rq_clock debug facility: bugs there cause latencies but no easily actionable symptoms, which are much harder to debug.

Thanks,

Ingo

I couldn't plug it into the production -ENOBOOT IO beasts from hell, but did run it on my little desktop a bit.

If watchdog gets credit for zillion disk detection time, it can end up throttled for what is effectively forever.

-Mike

My comment at the time was:

https://lkml.org/lkml/2014/4/8/295

Of course that debug patch doesn't apply anymore. But we've had so many fails with that skip_clock_update thing that we need more than yet another fudge without real means of validating stuff.

I'll go see if I can get that debug infra back up.

That has been a constant, yes. I can try with that disabled some time.

Dave

Here's my side of the story: I was observing RCU lockups which went away when I disabled verbose printing for fault injections. It seems that printing one line ~10 times a second can cause that...

I've disabled lock debugging to see if anything new will show up, and hit something that may be related:

[  787.894288] ================================================================================
[  787.897074] UBSan: Undefined behaviour in kernel/sched/fair.c:4541:17
[  787.898981] signed integer overflow:
[  787.900066] 361516561629678 * 101500 cannot be represented in type 'long long int'
[  787.900066] CPU: 18 PID: 12958 Comm: trinity-c103 Not tainted 3.18.0-rc6-next-20141201-sasha-00070-g028060a-dirty #1528
[  787.900066]  0000000000000000 0000000000000000 ffffffff93b0f890 ffff8806e3eff918
[  787.900066]  ffffffff91f1cf26 1ffffffff3c2de73 ffffffff93b0f8a8 ffff8806e3eff938
[  787.900066]  ffffffff91f1fb90 1ffffffff3c2de73 ffffffff93b0f8a8 ffff8806e3eff9f8
[  787.900066] Call Trace:
[  787.900066] dump_stack (lib/dump_stack.c:52)
[  787.900066] ubsan_epilogue (lib/ubsan.c:159)
[  787.900066] handle_overflow (lib/ubsan.c:191)
[  787.900066] ? __do_page_fault (arch/x86/mm/fault.c:1220)
[  787.900066] ? local_clock (kernel/sched/clock.c:392)
[  787.900066] __ubsan_handle_mul_overflow (lib/ubsan.c:218)
[  787.900066] select_task_rq_fair (kernel/sched/fair.c:4541 kernel/sched/fair.c:4755)
[  787.900066] try_to_wake_up (kernel/sched/core.c:1415 kernel/sched/core.c:1724)
[  787.900066] ? trace_hardirqs_on_thunk (arch/x86/lib/thunk_64.S:33)
[  787.900066] default_wake_function (kernel/sched/core.c:2979)
[  787.900066] ? get_parent_ip (kernel/sched/core.c:2559)
[  787.900066] autoremove_wake_function (kernel/sched/wait.c:295)
[  787.900066] ? get_parent_ip (kernel/sched/core.c:2559)
[  787.900066] __wake_up_common (kernel/sched/wait.c:73)
[  787.900066] __wake_up_sync_key (include/linux/spinlock.h:364 kernel/sched/wait.c:146)
[  787.900066] pipe_write (fs/pipe.c:466)
[  787.900066] ? kasan_poison_shadow (mm/kasan/kasan.c:48)
[  787.900066] ? new_sync_read (fs/read_write.c:480)
[  787.900066] do_iter_readv_writev (fs/read_write.c:681)
[  787.900066] compat_do_readv_writev (fs/read_write.c:1029)
[  787.900066] ? wait_for_partner (fs/pipe.c:340)
[  787.900066] ? _raw_spin_unlock (./arch/x86/include/asm/preempt.h:95 include/linux/spinlock_api_smp.h:152 kernel/locking/spinlock.c:183)
[  787.900066] ? __this_cpu_preempt_check (lib/smp_processor_id.c:63)
[  787.900066] ? syscall_trace_enter_phase1 (include/linux/context_tracking.h:27 arch/x86/kernel/ptrace.c:1486)
[  787.900066] compat_writev (fs/read_write.c:1145)
[  787.900066] compat_SyS_writev (fs/read_write.c:1163 fs/read_write.c:1151)
[  787.900066] ia32_do_call (arch/x86/ia32/ia32entry.S:446)
[  787.900066] ================================================================================

(For Linus asking himself "what the hell is this UBSan thing, I didn't merge that!" - it's an undefined behaviour sanitizer that works with gcc5.)

Thanks,
Sasha

Very interesting. But your source code doesn't match mine - can you say what that

    kernel/sched/fair.c:4541:17

line is?

There are at least five multiplications there (all inlined):

- "imbalance*min_load" from find_idlest_group()

- "factor * p->wakee_flips" in wake_wide()

- at least three in wake_affine:

"prev_eff_load *= capacity_of(this_cpu)"
"this_eff_load *= this_load + effective_load(tg, this_cpu, weight, weight)" "prev_eff_load *= load + effective_load(tg, prev_cpu, 0, weight)"

(There are other multiplications too, but they are by constants afaik and don't match yours).

None of those seem to have anything to do with the 3.16..3.17 changes, but I might be missing something, and obviously this also might have nothing to do with the problems anyway.

Adding Ingo/PeterZ to the participants again.

Linus

---

Sorry about that, I'm testing on the -next kernel. The relevant code snippet is in wake_affine:

        prev_eff_load = 100 + (sd->imbalance_pct - 100) / 2;
        prev_eff_load *= capacity_of(this_cpu);

        if (this_load > 0) {
                this_eff_load *= this_load +
                        effective_load(tg, this_cpu, weight, weight);  <==== This one

                prev_eff_load *= load + effective_load(tg, prev_cpu, 0, weight);
        }

Thanks,
Sasha

Just to add to this: I've enabled the simplest level of verbosity in the fault injection options, and RCU stalls are again easy to trigger:

[ 3926.110026] INFO: rcu_preempt detected stalls on CPUs/tasks:
[ 3926.110026] INFO: rcu_sched detected stalls on CPUs/tasks:
[ 3926.110026]  0: (62 ticks this GP) idle=b63/140000000000002/0 softirq=20384/20384 last_accelerate: f772/8874, nonlazy_posted: 619783, ..
[ 3926.110026]  (detected by 2, t=30002 jiffies, g=-222, c=-223, q=0)
[ 3926.110026] Task dump for CPU 0:
[ 3926.110026] kworker/dying   R  running task    13464     7      2 0x00080008
[ 3926.110026]  ffffffff814db441 ffff88006aa3bd68 ffffffff814db441 ffffe8fff3c6c9d4
[ 3926.110026]  00000000ffffffff ffff88006aa3bd88 ffffffff814db76b ffffffff93a27440
[ 3926.110026]  dfffe90000000000 ffff88006aa26890 ffff88006aa26000 ffff88006aa3b5d8
[ 3926.110026] Call Trace:
[ 3926.110026]  [<ffffffff814db441>] ? get_parent_ip+0x11/0x50
[ 3926.110026]  [<ffffffff814db441>] ? get_parent_ip+0x11/0x50
[ 3926.110026]  [<ffffffff814db76b>] ? preempt_count_sub+0x11b/0x1d0
[ 3926.110026]  [<ffffffff81429c57>] ? do_exit+0x1687/0x3f20
[ 3926.110026]  [<ffffffff81485578>] ? worker_thread+0xa28/0x1760
[ 3926.110026]  [<ffffffff81484b50>] ? process_one_work+0x17a0/0x17a0
[ 3926.110026]  [<ffffffff8149d719>] ? kthread+0x229/0x320
[ 3926.110026]  [<ffffffff8149d4f0>] ? kthread_worker_fn+0x7d0/0x7d0
[ 3926.110026]  [<ffffffff91ffc0fc>] ? ret_from_fork+0x7c/0xb0
[ 3926.110026]  [<ffffffff8149d4f0>] ? kthread_worker_fn+0x7d0/0x7d0
[ 3926.110033]
[ 3926.110033]  0: (62 ticks this GP) idle=b63/140000000000002/0 softirq=20384/20384 last_accelerate: f772/8876, nonlazy_posted: 619783, ..
[ 3926.110033]  (detected by 10, t=30004 jiffies, g=15638, c=15637, q=63609)
[ 3926.110033] Task dump for CPU 0:
[ 3926.110033] kworker/dying   R  running task    13464     7      2 0x00080008
[ 3926.110033]  ffffffff814db441 ffff88006aa3bd68 ffffffff814db441 ffffe8fff3c6c9d4
[ 3926.110033]  00000000ffffffff ffff88006aa3bd88 ffffffff814db76b ffffffff93a27440
[ 3926.110033]  dfffe90000000000 ffff88006aa26890 ffff88006aa26000 ffff88006aa3b5d8
[ 3926.110033] Call Trace:
[ 3926.110033]  [<ffffffff814db441>] ? get_parent_ip+0x11/0x50
[ 3926.110033]  [<ffffffff814db441>] ? get_parent_ip+0x11/0x50
[ 3926.110033]  [<ffffffff814db76b>] ? preempt_count_sub+0x11b/0x1d0
[ 3926.110033]  [<ffffffff81429c57>] ? do_exit+0x1687/0x3f20
[ 3926.110033]  [<ffffffff81485578>] ? worker_thread+0xa28/0x1760
[ 3926.110033]  [<ffffffff81484b50>] ? process_one_work+0x17a0/0x17a0
[ 3926.110033]  [<ffffffff8149d719>] ? kthread+0x229/0x320
[ 3926.110033]  [<ffffffff8149d4f0>] ? kthread_worker_fn+0x7d0/0x7d0
[ 3926.110033]  [<ffffffff91ffc0fc>] ? ret_from_fork+0x7c/0xb0
[ 3926.110033]  [<ffffffff8149d4f0>] ? kthread_worker_fn+0x7d0/0x7d0

Thanks,
Sasha

Where do you log to?

In particular, do you have some serial line logging enabled (perhaps even without anybody listening)? Or network logging?

We've definitely had cases where logging itself is so slow that it triggers watchdogs etc. Logging to a serial line can take for*ever* in modern terms..

Linus

Yes, it's going to a serial line, but it's only about 100 lines/second on average. I wouldn't expect it to cause anything to hang!

Thanks,
Sasha

A regular 16650 serial chip? Running at 115kbps, I assume? So that's about 11kB/s.

And the serial console is polling, since it can't sleep or depend on interrupts.

At a average line length of what, 40 characters? At less than 300 lines/s, you'd be using up 100% of one CPU. And since the printouts are serialized, that would be all other CPU's too..

100 lines/s _average_ means that I can easily see it be 300lines/s for a while.

So yeah. The serial console is simply not designed to handle continuous output. It's for the "occasional" stuff.

The fact that your rcu lockups go away when you make the fault injection be quiet makes me really suspect this is related.

Linus

The lockups themselves "go away", but looking closer at the log without those extra prints, I'm seeing:

[ 1458.700070] INFO: rcu_preempt detected stalls on CPUs/tasks:
[ 1458.700133]  (detected by 19, t=30502 jiffies, g=12293, c=12292, q=0)
[ 1458.702764] INFO: Stall ended before state dump start

Quite often.

Maybe the extra prints were just a catalyst?

Thanks,
Sasha

Is anything else being printed about the time that these message show up? Or is this the only output for the 40,000 jiffies preceding this message?

Thanx, Paul

And could you please build with CONFIG_RCU_CPU_STALL_INFO=y and try this again?

Thanx, Paul

There's actually nothing going on (beyond fuzzing noise) before/after:

[  756.618342] kexec-bzImage64: Not a bzImage
[  762.381734] kexec-bzImage64: Not a bzImage
[  765.129612] Unable to find swap-space signature
[  771.022304] Unable to find swap-space signature
[  793.434417] kexec-bzImage64: Not a bzImage
[  797.978210] => alloc_cpumask_var: failed!
[  800.253116] kexec-bzImage64: Not a bzImage
[  818.280056] INFO: rcu_sched detected stalls on CPUs/tasks:
[  818.280056]  (detected by 11, t=30503 jiffies, g=-295, c=-296, q=0)
[  818.283400] INFO: Stall ended before state dump start
[  829.523992] audit: type=1326 audit(39.680:47): auid=4294967295 uid=2385760256 gid=2214330370 ses=4294967295 pid=13307 comm="trinity-c353" exe="/trinity/trinity" sig=9 arch=c000003e syscall=96 compat=0 ip=0x7fffcb7bee47 code=0x0
[  830.890841] audit: type=1326 audit(41.010:48): auid=4294967295 uid=310902784 gid=201841673 ses=4294967295 pid=13294 comm="trinity-c350" exe="/trinity/trinity" sig=9 arch=c000003e syscall=96 compat=0 ip=0x7fffcb7bee47 code=0x0

I already have it set:

$ grep STALL_INFO .config
CONFIG_RCU_CPU_STALL_INFO=y

Thanks,
Sasha

I have seen this caused by lost IPIs, but you have to lose two of them, which seems less than fully likely.

Ah, apologies. OK, time to make this the default, and later to remove the option...

Thanx, Paul

It does seem that it can cause full blown stalls as well, just pretty rarely (notice the lack of any prints before):

[11373.032327] audit: type=1326 audit(1397703594.974:502): auid=4294967295 uid=7884781 gid=0 ses=4294967295 pid=9853 comm="trinity-c768" exe="/trinity/trinity" sig=9 arch=c0000
03e syscall=96 compat=0 ip=0x7fff2c3fee47 code=0x0
[11374.565881] audit: type=1326 audit(1397703596.504:503): auid=4294967295 uid=32 gid=0
 ses=4294967295 pid=9801 comm="trinity-c710" exe="/trinity/trinity" sig=9 arch=c000003e syscall=96 compat=0 ip=0x7fff2c3fee47 code=0x0
[11839.353539] Hangcheck: hangcheck value past margin!
[12040.010128] INFO: rcu_sched detected stalls on CPUs/tasks:
[12040.012072]  (detected by 4, t=213513 jiffies, g=-222, c=-223, q=0)
[12040.014200] INFO: Stall ended before state dump start
[12159.730069] INFO: rcu_preempt detected stalls on CPUs/tasks:
[12159.730069]  (detected by 3, t=396537 jiffies, g=24095, c=24094, q=1346)
[12159.730069] INFO: Stall ended before state dump start
[12602.162439] Hangcheck: hangcheck value past margin!
[12655.560806] INFO: rcu_sched detected stalls on CPUs/tasks:
[12655.560806]  0: (3 ticks this GP) idle=bc3/140000000000002/0 softirq=26674/26674 last_accelerate: b2a8/da68, nonlazy_posted: 20893, ..
[12655.602171]  (detected by 13, t=30506 jiffies, g=-219, c=-220, q=0)
[12655.602171] Task dump for CPU 0:
[12655.602171] trinity-c39     R  running task    11904  6558  26120 0x0008000c
[12655.602171]  ffffffff81593bf7 ffff8808d5d58d40 0000000000000282 ffffffff9ef40538
[12655.602171]  ffff880481400000 ffff8808d5dcb638 ffffffff83f2ed2b ffffffff9eaa1718
[12655.602171]  ffff8808d5d58d08 00000b820c44b0ae 0000000000000000 0000000000000001
[12655.602171] Call Trace:
[12655.602171]  [<ffffffff81593bf7>] ? trace_hardirqs_on_caller+0x677/0x900
[12655.602171]  [<ffffffff83f2ed2b>] ? trace_hardirqs_on_thunk+0x3a/0x3f
[12655.602171]  [<ffffffff91677ffb>] ? retint_restore_args+0x13/0x13
[12655.602171]  [<ffffffff91676612>] ? _raw_spin_unlock_irqrestore+0xa2/0xf0
[12655.602171]  [<ffffffff83f93705>] ? __debug_check_no_obj_freed+0x2f5/0xd90
[12655.602171]  [<ffffffff81593bf7>] ? trace_hardirqs_on_caller+0x677/0x900
[12655.602171]  [<ffffffff83f95ba9>] ? debug_check_no_obj_freed+0x19/0x20
[12655.602171]  [<ffffffff819049bf>] ? free_pages_prepare+0x5bf/0x1000
[12655.602171]  [<ffffffff83f90fe3>] ? __this_cpu_preempt_check+0x13/0x20
[12655.602171]  [<ffffffff8190cacd>] ? __free_pages_ok+0x3d/0x360
[12655.602171]  [<ffffffff8190ce7d>] ? free_compound_page+0x8d/0xd0
[12655.602171]  [<ffffffff81929986>] ? __put_compound_page+0x46/0x70
[12655.602171]  [<ffffffff8192b395>] ? put_compound_page+0xf5/0x10e0
[12655.602171]  [<ffffffff814d99ab>] ? preempt_count_sub+0x11b/0x1d0
[12655.602171]  [<ffffffff8192da4d>] ? release_pages+0x41d/0x6f0
[12655.602171]  [<ffffffff81a0188b>] ? free_pages_and_swap_cache+0x11b/0x1a0
[12655.602171]  [<ffffffff819a6b92>] ? tlb_flush_mmu_free+0x72/0x180
[12655.602171]  [<ffffffff819ace76>] ? unmap_single_vma+0x1326/0x2170
[12655.602171]  [<ffffffff83f90fe3>] ? __this_cpu_preempt_check+0x13/0x20
[12655.602171]  [<ffffffff819b0644>] ? unmap_vmas+0xd4/0x250
[12655.602171]  [<ffffffff819d62c9>] ? exit_mmap+0x169/0x610
[12655.602171]  [<ffffffff81a678fd>] ? kmem_cache_free+0x7cd/0xbb0
[12655.602171]  [<ffffffff814095b2>] ? mmput+0xd2/0x2c0
[12655.602171]  [<ffffffff81423551>] ? do_exit+0x7e1/0x39c0
[12655.602171]  [<ffffffff81456fb2>] ? get_signal+0x7a2/0x2130
[12655.602171]  [<ffffffff81426891>] ? do_group_exit+0x101/0x490
[12655.602171]  [<ffffffff814d99ab>] ? preempt_count_sub+0x11b/0x1d0
[12655.602171]  [<ffffffff81456f4e>] ? get_signal+0x73e/0x2130
[12655.602171]  [<ffffffff811d59f1>] ? sched_clock+0x31/0x50
[12655.602171]  [<ffffffff81585ded>] ? get_lock_stats+0x1d/0x100
[12655.602171]  [<ffffffff811ac828>] ? do_signal+0x28/0x3750
[12655.602171]  [<ffffffff814f7f73>] ? vtime_account_user+0x173/0x220
[12655.602171]  [<ffffffff814d96c1>] ? get_parent_ip+0x11/0x50
[12655.602171]  [<ffffffff83f90fe3>] ? __this_cpu_preempt_check+0x13/0x20
[12655.602171]  [<ffffffff81593bf7>] ? trace_hardirqs_on_caller+0x677/0x900
[12655.602171]  [<ffffffff81593e8d>] ? trace_hardirqs_on+0xd/0x10
[12655.602171]  [<ffffffff811affb9>] ? do_notify_resume+0x69/0x100
[12655.602171]  [<ffffffff9167744f>] ? int_signal+0x12/0x17

Thanks,
Sasha

Forgot to mentioned, I cranked the rcu lockup timeout to 300 seconds and got that stall.

Thanks,
Sasha

So with the default of 21 seconds, you presumably get huge numbers of RCU CPU stall warnings?

Thanx, Paul

Yes, I'm seeing 1 lockup every ~5 minutes on my set up.

The traces do seem to be different every time.

Thanks,
Sasha

This is back in the TLB-flush and free-pagef arena. But unless you have an extremely large process, I wouldn't expect this to take 30K jiffies.

And the above is what I was looking for from RCU_CPU_STALL_INFO, thank you!

This CPU only saw three scheduling-clock ticks during this grace period, which suggests that your workload is not very intense or that you are running NO_HZ_FULL with this CPU having a single CPU-bound userspace task.

The CPU is currently not idle (no surprise). There has been no softirq activity during this grace period. There was at least one callback acceleration during this grace period (irrelevant to this bug), and there have been more than 26K non-lazy callbacks posted during this grace period (no surprise, given that the grace period has been in force for more than 30K jiffies).

Thanx, Paul

So there's an interesting change in between 3.16..3.17 - a commit that was already reverted once due to unrelated problems (it apparently hit lockdep issues): commit 5874af2003b1 ("printk: enable interrupts before calling console_trylock_for_printk()").

In particular, that commit means that interrupts get re-enabled in the middle of the printk (if they were enabled before the printk), and while I don't see why that would be wrong, it definitely might change behavior. That code has often been fragile (the whole lockdep example was just the latest case of that). For example, it ends up looping over "goto again" with preemption disabled if new console messages keep coming in.

So I don't think that "enable interrupts" commit itself is necessarily buggy, but looking at all the printk changes in the relevant time range, I can easily see that particular commit having some subtle interaction under heavy printk activity. Before that commit, all the queued printouts would be written with interrupts disabled all the way. After that commit, interrupts get re-enabled before and in between messages get actually pushed to the console.

Should it matter? No. But I don't think we figured out what went wrong with the lockdep issue that an earlier version of that commit had either, and that problem caused lockups at boot for some people. The whole "print to console" is just fragile, and the addition of serial console migth just make it even worse.

I dunno. But especially since your RCU issues seem to solve themselves when *not* having lots of printk's, maybe the lockup is somehow related to this all. Maybe the lockdep recursion hang ends up being a "RCU debugging" hang when the timer interrupt causes printk recursion with the console lock held..

Linus

I periodically switch PREEMPT options, just to see if anything new falls out, though I've been on CONFIG_PREEMPT for quite a while. So right now I'm testing the TREE_PREEMPT_RCU case.

I'm in the process of bisecting 3.16 -> 3.17 (currently on -rc1) Thanksgiving kind of screwed up my flow, but 3.16 got a real pounding for over 3 days with no problems.
I can give a !PREEMPT_RCU build a try, in case that turns out to point to something quicker than a bisect is going to.

I don't recall a kernel where I didn't see RCU oddities of some description, but in recent times, not so much, though a few releases back I did change some of the RCU related CONFIG options while Paul & co were chasing down some bugs.

These days I've been running with..

# RCU Subsystem
CONFIG_TREE_PREEMPT_RCU=y
CONFIG_PREEMPT_RCU=y
# CONFIG_TASKS_RCU is not set
CONFIG_RCU_STALL_COMMON=y
# CONFIG_RCU_USER_QS is not set
CONFIG_RCU_FANOUT=64
CONFIG_RCU_FANOUT_LEAF=16
# CONFIG_RCU_FANOUT_EXACT is not set
CONFIG_TREE_RCU_TRACE=y
CONFIG_RCU_BOOST=y
CONFIG_RCU_BOOST_PRIO=1
CONFIG_RCU_BOOST_DELAY=500
CONFIG_RCU_NOCB_CPU=y
# CONFIG_RCU_NOCB_CPU_NONE is not set
# CONFIG_RCU_NOCB_CPU_ZERO is not set
CONFIG_RCU_NOCB_CPU_ALL=y
CONFIG_DEBUG_OBJECTS_RCU_HEAD=y
# RCU Debugging
CONFIG_SPARSE_RCU_POINTER=y
# CONFIG_RCU_TORTURE_TEST is not set
CONFIG_RCU_CPU_STALL_TIMEOUT=60
CONFIG_RCU_CPU_STALL_VERBOSE=y
CONFIG_RCU_CPU_STALL_INFO=y
CONFIG_RCU_TRACE=y

Dave

No,. go on with the bisect. I think at this point we'll all be happier narrowing down the range of commits than anything else. The behavior Dâniel sees may be entirely unrelated anyway.

Linus

That combination doesn't seem possible. TREE_PREEMPT_RCU is the only possible choice if PREEMPT=y

Dave

Indeed, getting that combination requires a Kconfig patch, which I supplied below. Not for mainline, debugging only.

Thanx, Paul

------------------------------------------------------------------------

index 903505e66d1d..2cf71fcd514f 100644
@@ -469,7 +469,7 @@ choice
 
 config TREE_RCU
 	bool "Tree-based hierarchical RCU"
-	depends on !PREEMPT && SMP
+	depends on SMP
 	select IRQ_WORK
 	help
 	  This option selects the RCU implementation that is

Well, this turned out to be way simpler than I expected. Passes light rcutorture testing. Sometimes you get lucky...

Thanx, Paul

index 903505e66d1d..2cf71fcd514f 100644
@@ -469,7 +469,7 @@ choice
 
 config TREE_RCU
 	bool "Tree-based hierarchical RCU"
-	depends on !PREEMPT && SMP
+	depends on SMP
 	select IRQ_WORK
 	help
 	  This option selects the RCU implementation that is

Linus, Paul and others, I finally got a call trace with
only CONFIG_TREE_PREEMPT_RCU *disabled* using Paul's patch (to trigger it I compiled PHP with make -j8).

Dec  2 14:24:39 tux kernel: [ 8475.941616] conftest[9730]: segfault at 0 ip 0000000000400640 sp 00007fffa67ab300 error 4 in conftest[400000+1000]
Dec  2 14:24:40 tux kernel: [ 8476.104725] conftest[9753]: segfault at 0 ip 00007f6863024906 sp 00007fff0e31cc48 error 4 in libc-2.19.so[7f6862efe000+1a1000]
Dec  2 14:25:54 tux kernel: [ 8550.791697] INFO: rcu_sched detected stalls on CPUs/tasks: { 4} (detected by 0, t=60002 jiffies, g=112854, c=112853, q=0)
Dec  2 14:25:54 tux kernel: [ 8550.791702] Task dump for CPU 4:
Dec  2 14:25:54 tux kernel: [ 8550.791703] cc1             R  running task        0 14344  14340 0x00080008
Dec  2 14:25:54 tux kernel: [ 8550.791706]  000000001bcebcd8 ffff880100000003 ffffffff810cb7f1 ffff88021f5f5c00
Dec  2 14:25:54 tux kernel: [ 8550.791708]  ffff88011bcebfd8 ffff88011bcebce8 ffffffff811fb970 ffff8802149a2a00
Dec  2 14:25:54 tux kernel: [ 8550.791710]  ffff8802149a2cc8 ffff88011bcebd28 ffffffff8103e979 ffff88020ed01398
Dec  2 14:25:54 tux kernel: [ 8550.791712] Call Trace:
Dec  2 14:25:54 tux kernel: [ 8550.791718]  [<ffffffff810cb7f1>] ? release_pages+0xa1/0x1e0
Dec  2 14:25:54 tux kernel: [ 8550.791722]  [<ffffffff811fb970>] ? cpumask_any_but+0x30/0x40
Dec  2 14:25:54 tux kernel: [ 8550.791725]  [<ffffffff8103e979>] ? flush_tlb_page+0x49/0xf0
Dec  2 14:25:54 tux kernel: [ 8550.791727]  [<ffffffff810cbe72>] ? lru_cache_add_active_or_unevictable+0x22/0x90
Dec  2 14:25:54 tux kernel: [ 8550.791731]  [<ffffffff810fc4c2>] ? alloc_pages_vma+0x72/0x130
Dec  2 14:25:54 tux kernel: [ 8550.791733]  [<ffffffff810cbe72>] ? lru_cache_add_active_or_unevictable+0x22/0x90
Dec  2 14:25:54 tux kernel: [ 8550.791735]  [<ffffffff810e5220>] ? handle_mm_fault+0x3a0/0xaf0
Dec  2 14:25:54 tux kernel: [ 8550.791737]  [<ffffffff81039074>] ? __do_page_fault+0x224/0x4c0
Dec  2 14:25:54 tux kernel: [ 8550.791740]  [<ffffffff8110d54c>] ? new_sync_write+0x7c/0xb0
Dec  2 14:25:55 tux kernel: [ 8550.791743]  [<ffffffff8114765c>] ? fsnotify+0x27c/0x350
Dec  2 14:25:55 tux kernel: [ 8550.791746]  [<ffffffff81087233>] ? rcu_eqs_enter+0x93/0xa0
Dec  2 14:25:55 tux kernel: [ 8550.791748]  [<ffffffff81087a5e>] ? rcu_user_enter+0xe/0x10
Dec  2 14:25:55 tux kernel: [ 8550.791749]  [<ffffffff8103938a>] ? do_page_fault+0x5a/0x70
Dec  2 14:25:55 tux kernel: [ 8550.791752]  [<ffffffff8139d9d2>] ? page_fault+0x22/0x30

If you need more info/testing, just ask.

Linux 3.17.0-dirty: Shuffling Zombie Juror
http://www.youtube.com/DanielFragaBR
http://exchangewar.info
Bitcoin: 12H6661yoLDUZaYPdah6urZS5WiXwTAUgL

Is it harder to reproduce with CONFIG_PREEMPT=y and CONFIG_TREE_PREEMPT_RCU=n?

If it is a -lot- harder to reproduce, it might be worth bisecting among the RCU read-side critical sections. If making a few of them be non-preemptible greatly reduces the probability of the bug occuring, that might provide a clue about root cause.

On the other hand, if it is just a little harder to reproduce, this RCU read-side bisection would likely be an exercise in futility.

Thanx, Paul

Yes, it's much harder! :)

Ok, I want to bisect it. Since it could be painful to bisect,
could you suggest 2 commits between 3.16.0 and 3.17.0 so we can narrow the bisect? I could just bisect between 3.16.0 and 3.17.0 but it would take many days :).

Ps: if you prefer I bisect between 3.16.0 and 3.17.0, no
problem, but you'll have to be patient ;).

Linux 3.17.0-dirty: Shuffling Zombie Juror
http://www.youtube.com/DanielFragaBR
http://exchangewar.info
Bitcoin: 12H6661yoLDUZaYPdah6urZS5WiXwTAUgL

I was actually suggesting something a bit different. Instead of bisecting by release, bisect by code. The procedure is as follows:

1. I figure out some reliable way of making RCU allow preemption to
be disabled for some RCU read-side critical sections, but not for others. I send you the patch, which has rcu_read_lock_test() as well as rcu_read_lock().

2. You build a kernel without my Kconfig hack, with my patch from
#1 above, and build a kernel with CONFIG_PREEMPT=y (which of course implies CONFIG_TREE_PREEMPT_RCU=y, given that you are building without my Kconfig hack).

3. You make a list of all the rcu_read_lock() uses in the kernel
(or ask me to provide it). You change the rcu_read_lock() calls in the first half of this list to rcu_read_lock_test().

If the kernel locks up as easily with this change as it did in a stock CONFIG_PREEMPT=y CONFIG_TREE_PREEMPT_RCU=y kernel, change half of the remaining rcu_read_lock() calls to rcu_read_lock_test(). If the kernel is much more resistant to lockup, change half of the rcu_read_lock_test() calls back to rcu_read_lock().

4. It is quite possible that several of the RCU read-side critical
sections contribute to the unreliability, in which case the bisection will get a bit more complicated.

Other thoughts on how to attack this?

Thanx, Paul

Ok Paul, I want to do everything I can to help you debug this.

So can you provide me the list you mentioned at point 3 (or
tell me how can I get it)? If you guide me through this, I can do whatever you need. Thanks!

Linux 3.17.0-rc6-00235-gb94d525: Shuffling Zombie Juror
http://www.youtube.com/DanielFragaBR
http://exchangewar.info
Bitcoin: 12H6661yoLDUZaYPdah6urZS5WiXwTAUgL

OK. I need to know exactly what version of the Linux kernel you are using. 3.18-rc7? (I am not too worried about exactly which version you are using as long as I know which version it is.)

Thanx, Paul

Ok, I stopped bisecting and went back to 3.17.0 stock kernel.
I'm testing with 3.17.0 kernel because this one is the first to show problems. If you want me to go to 3.18-rc7, just ask I can checkout through git.

Ps: my signature will reflect the kernel I'm using now ;)

Linux 3.17.0: Shuffling Zombie Juror
http://www.youtube.com/DanielFragaBR
http://exchangewar.info
Bitcoin: 12H6661yoLDUZaYPdah6urZS5WiXwTAUgL

And I left out a step. Let's make sure that my preempt_disabled() hack to CONFIG_TREE_PREEMPT_RCU=y has the same effect as the Kconfig hack that allowed CONFIG_PREEMPT=y and CONFIG_TREE_PREEMPT_RCU=n. Could you please try out the following patch configured with CONFIG_PREEMPT=y and CONFIG_TREE_PREEMPT_RCU=y?

Thanx, Paul

------------------------------------------------------------------------

index e0d31a345ee6..fff605a9e87f 100644
@@ -71,7 +71,11 @@ module_param(rcu_expedited, int, 0);
  */
 void __rcu_read_lock(void)
 {
-	current->rcu_read_lock_nesting++;
+	struct task_struct *t = current;
+
+	if (!t->rcu_read_lock_nesting)
+		preempt_disable();
+	t->rcu_read_lock_nesting++;
 	barrier();  /* critical section after entry code. */
 }
 EXPORT_SYMBOL_GPL(__rcu_read_lock);

@@ -92,6 +96,7 @@ void __rcu_read_unlock(void)
 	} else {
 		barrier();  /* critical section before exit code. */
 		t->rcu_read_lock_nesting = INT_MIN;
+		preempt_enable();
 		barrier();  /* assign before ->rcu_read_unlock_special load */
 		if (unlikely(ACCESS_ONCE(t->rcu_read_unlock_special.s)))
 			rcu_read_unlock_special(t);

Of course! I applied your patch to 3.17 stock kernel and after
stressing it (compiling with -j8 and watching videos on Youtube) to trigger the bug I got the following:

Dec  2 19:47:25 tux kernel: [  927.973547] INFO: rcu_preempt detected stalls on CPUs/tasks: { 5} (detected by 1, t=60002 jiffies, g=71142, c=71141, q=0)
Dec  2 19:47:26 tux kernel: [  927.973553] Task dump for CPU 5:
Dec  2 19:47:26 tux kernel: [  927.973555] cc1             R  running task        0 30691  30680 0x00080008
Dec  2 19:47:26 tux kernel: [  927.973558]  ffff88021f351bc0 ffff8801d5743f00 ffffffff8107062a ffff88021f351c38
Dec  2 19:47:26 tux kernel: [  927.973560]  ffff8801d5743ea8 ffff8800cd3b0000 ffff8800cd3b041c 0000000000000000
Dec  2 19:47:26 tux kernel: [  927.973562]  00007f89b4d7d8e8 00007f89b5939a60 ffff88021f34d2c0 00007f89b4d7f000
Dec  2 19:47:26 tux kernel: [  927.973564] Call Trace:
Dec  2 19:47:26 tux kernel: [  927.973573]  [<ffffffff8107062a>] ? pick_next_task_fair+0x6aa/0x890
Dec  2 19:47:26 tux kernel: [  927.973577]  [<ffffffff81087483>] ? rcu_eqs_enter+0x93/0xa0
Dec  2 19:47:26 tux kernel: [  927.973579]  [<ffffffff81087f2e>] ? rcu_user_enter+0xe/0x10
Dec  2 19:47:26 tux kernel: [  927.973582]  [<ffffffff8103935a>] ? do_page_fault+0x5a/0x70
Dec  2 19:47:26 tux kernel: [  927.973585]  [<ffffffff8139bed2>] ? page_fault+0x22/0x30
Dec  2 19:47:30 tux kernel: [  932.471964] CPU1: Core temperature above threshold, cpu clock throttled (total events = 820)
Dec  2 19:47:30 tux kernel: [  932.471966] CPU6: Package temperature above threshold, cpu clock throttled (total events = 2624)
Dec  2 19:47:30 tux kernel: [  932.471967] CPU3: Package temperature above threshold, cpu clock throttled (total events = 2624)
Dec  2 19:47:30 tux kernel: [  932.471968] CPU7: Package temperature above threshold, cpu clock throttled (total events = 2624)
Dec  2 19:47:30 tux kernel: [  932.471969] CPU0: Package temperature above threshold, cpu clock throttled (total events = 2624)
Dec  2 19:47:30 tux kernel: [  932.471970] CPU2: Package temperature above threshold, cpu clock throttled (total events = 2624)
Dec  2 19:47:30 tux kernel: [  932.471978] CPU1: Package temperature above threshold, cpu clock throttled (total events = 2624)
Dec  2 19:47:30 tux kernel: [  932.472922] CPU1: Core temperature/speed normal
Dec  2 19:47:30 tux kernel: [  932.472923] CPU6: Package temperature/speed normal
Dec  2 19:47:31 tux kernel: [  932.472923] CPU2: Package temperature/speed normal
Dec  2 19:47:31 tux kernel: [  932.472924] CPU3: Package temperature/speed normal
Dec  2 19:47:31 tux kernel: [  932.472925] CPU0: Package temperature/speed normal

Waiting for your next instructions.

Linux 3.17.0-dirty: Shuffling Zombie Juror
http://www.youtube.com/DanielFragaBR
http://exchangewar.info
Bitcoin: 12H6661yoLDUZaYPdah6urZS5WiXwTAUgL

So it appears that you can recreate this much more quickly than DaveJ can recreate his issue.

The two issues may be entirely unrelated, but the it is certainly quite possible that they have some relation to each other, and the timing is intriguing, in that 3.17 seems to be the first kernel release this happened in.

So at this point I think I'd ask you to just go back to your bisection that you apparently already started earlier. I take it 3.16 worked fine, and that's what you used as the good base for your bisect?

Even if it's something else than what DaveJ sees (or perhaps *particularly* if it's something else), bisecting when it started would be very worthwhile.

There's 13k+ commits in between 3.16 and 3.17, so a full bisect should be around 15 test-points. But judging by the timing of your emails, you can generally reproduce this relatively quickly..

Linus

No problem Linus. I'll try the full bisect and I post here
later with the final result.

Linux 3.17.0-dirty: Shuffling Zombie Juror
http://www.youtube.com/DanielFragaBR
http://exchangewar.info
Bitcoin: 12H6661yoLDUZaYPdah6urZS5WiXwTAUgL

Ok Linus and Paul, it took me almost 5 hours to bisect it and
the result is:

c9b88e9581828bb8bba06c5e7ee8ed1761172b6e is the first bad commit

http://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/commit/?id=c9b88e9581828bb8bba06c5e7ee8ed1761172b6e

I hope I didn't get any false positive/negative during
bisect.

And here's the complete bisect log (just in case):

git bisect start
# good: [19583ca584d6f574384e17fe7613dfaeadcdc4a6] Linux 3.16
git bisect good 19583ca584d6f574384e17fe7613dfaeadcdc4a6
# bad: [bfe01a5ba2490f299e1d2d5508cbbbadd897bbe9] Linux 3.17
git bisect bad bfe01a5ba2490f299e1d2d5508cbbbadd897bbe9
# bad: [f2d7e4d4398092d14fb039cb4d38e502d3f019ee] checkpatch: add fix_insert_line and fix_delete_line helpers
git bisect bad f2d7e4d4398092d14fb039cb4d38e502d3f019ee
# bad: [79eb238c76782a59d51adf8a3dd7f6444245b475] Merge tag 'tty-3.17-rc1' of git://git.kernel.org/pub/scm/linux/kernel/git/gregkh/tty
git bisect bad 79eb238c76782a59d51adf8a3dd7f6444245b475
# good: [3d582487beb83d650fbd25cb65688b0fbedc97f1] staging: vt6656: struct vnt_private pInterruptURB rename to interrupt_urb git bisect good 3d582487beb83d650fbd25cb65688b0fbedc97f1
# bad: [e9c9eecabaa898ff3fedd98813ee4ac1a00d006a] Merge branch 'x86-cpufeature-for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip
git bisect bad e9c9eecabaa898ff3fedd98813ee4ac1a00d006a
# bad: [c9b88e9581828bb8bba06c5e7ee8ed1761172b6e] Merge tag 'trace-3.17-2' of git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace
git bisect bad c9b88e9581828bb8bba06c5e7ee8ed1761172b6e
# good: [47dfe4037e37b2843055ea3feccf1c335ea23a9c] Merge branch 'for-3.17' of git://git.kernel.org/pub/scm/linux/kernel/git/tj/cgroup
git bisect good 47dfe4037e37b2843055ea3feccf1c335ea23a9c
# good: [b11a6face1b6d5518319f797a74e22bb4309daa9] clk: Add missing of_clk_set_defaults export
git bisect good b11a6face1b6d5518319f797a74e22bb4309daa9
# good: [3a636388bae8390d23f31e061c0c6fdc14525786] tracing: Remove function_trace_stop and HAVE_FUNCTION_TRACE_MCOUNT_TEST git bisect good 3a636388bae8390d23f31e061c0c6fdc14525786
# good: [e17acfdc83b877794c119fac4627e80510ea3c09] Merge branch 'for-3.17' of git://git.kernel.org/pub/scm/linux/kernel/git/tj/libata
git bisect good e17acfdc83b877794c119fac4627e80510ea3c09
# good: [c7ed326fa7cafb83ced5a8b02517a61672fe9e90] Merge tag 'ktest-v3.17' of git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-ktest
git bisect good c7ed326fa7cafb83ced5a8b02517a61672fe9e90
# good: [dc6f03f26f570104a2bb03f9d1deb588026d7c75] ftrace: Add warning if tramp hash does not match nr_trampolines
git bisect good dc6f03f26f570104a2bb03f9d1deb588026d7c75
# good: [ede392a75090aab49b01ecd6f7694bb9130ad461] tracing/uprobes: Kill the dead TRACE_EVENT_FL_USE_CALL_FILTER logic
git bisect good ede392a75090aab49b01ecd6f7694bb9130ad461
# good: [bb9ef1cb7d8668d6b0038b6f9f783c849135e40d] tracing: Change apply_subsystem_event_filter() paths to check file->system == dir git bisect good bb9ef1cb7d8668d6b0038b6f9f783c849135e40d
# good: [6355d54438bfc3b636cb6453cd091f782fb9b4d7] tracing: Kill "filter_string" arg of replace_preds()
git bisect good 6355d54438bfc3b636cb6453cd091f782fb9b4d7
# good: [b8c0aa46b3e86083721b57ed2eec6bd2c29ebfba] Merge tag 'trace-3.17' of git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace
git bisect good b8c0aa46b3e86083721b57ed2eec6bd2c29ebfba

# first bad commit: [c9b88e9581828bb8bba06c5e7ee8ed1761172b6e] Merge tag 'trace-3.17-2' of git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace

Linux 3.16.0-00409-gb8c0aa4: Shuffling Zombie Juror
http://www.youtube.com/DanielFragaBR
http://exchangewar.info
Bitcoin: 12H6661yoLDUZaYPdah6urZS5WiXwTAUgL

Much faster than I expected. However:

Hgghnn.. A merge commit can certainly be the thing that introduces bugs, but it *usually* isn't. Especially not one that is fairly small and has no actual conflcts in it. Sure, there could be semantics conflicts etc, but that's where "fairly small" comes in - that is just not a complicated or subtle merge. And there are other reasons to believe your bisection weered off into the weeds earlier. Read on.

So:

Well, the "bad" ones should be pretty safe, since there is no question at all about any case where things locked up. So unless you actually mis-typed or did something other silly, I'll trust the ones you marked bad.

It's the ones marked "good" that are more questionable, and might be wrong, because you didn't run for long enough, and didn't happen to hit the right condition.

Your bisection log also kind of points to a mistake: it ends with a long run of "all good". That usually means that you're not actually getting closer to the bug: if you were, you'd - pretty much by definition - also get closer to the "edge" of the bug, and you should generally see a mix of good/bad as you narrow in on it. Of course, it's all statistical, so I'm not saying that a run of "good" bisections is a sure-fire sign of anything, but it's just another
sign: you may have marked something "good" that wasn't, and that actually took you *away* from the bug, so now everything that followed that false positive was good.

So this part I'll believe in:

because anything marked "bad" clearly must be bad, and anything you marked "good" before that was probably correct too - because you saw "bad" cases after it, the good marking clearly hadn't made us ignore the bug.

Put another way: "bad" is generally more trustworthy (because you actively saw the bug), while a "good" _before_ a subsequent bad is also trustworthy (because if the "good" kernel contained the bug and you should have marked it bad, we'd then go on to test all the commits that were *not* the bug, so we'd never see a "bad" kernel again).

Of course, the above rule-of-thumb is a simplification of reality. In reality, there might be multiple bugs that come together and make the whole good-vs-bad a much less black-and-white thing, but *generally* I trust "git bisect bad" more than "git bisect good", and "git bisect good" that is followed by "bad".

What is *really* suspicious is a series of "git bisect good" with no "bad"s anywhere. Which is exactly what we see at the end of the bisect.

So might I ask you to try starting from this point again (this is why the bisect log is so useful - no need to retest the above part, you can just mindlessly do that sequence by hand without testing), and starting with this commit:

Double-check whether that commit is really good. Run that "good" kernel for a longer time, and under heavier load. Just to verify.

Because looking at the part of the bisect that seems trust-worthy, and looking at what remains (hint: do "gitk --bisect" while bisecting to see what is going on), these are the merges in that set (in my "mergelog" format):

Bjorn Helgaas (1):
PCI updates

Borislav Petkov (1):
EDAC changes

Herbert Xu (1):
crypto update

Jeff Layton (1):
file locking related changes

Mike Turquette (1):
clock framework updates

Steven Rostedt (3):
config-bisect changes
tracing updates
tracing filter cleanups

Tejun Heo (4):
workqueue updates
percpu updates
cgroup changes
libata changes

and quite frankly, for some core bug like this, I'd suspsect the workqueue or percpu updates from Tejun (possibly cgroup), *not* the tracing pull.

Of course, bugs can come in from anywhere, so it *could* be the tracing one, and it *could* be the merge commit, but my gut just screams that you probably missed one bad kernel, and marked it good. And it's really that very first one (ie commit 47dfe4037e37b2843055ea3feccf1c335ea23a9c) that contains most of the actually suspect code, so I'd really like you to re-test that one a lot before you call it "good" again.

Humor me.

I added Tejun to the Cc, just because I wanted to give him a heads-up that I am tentatively starting to blame him in my dark little mind..

Linus

	:)

	I understand Linus. I'll try the 47dfe4037 commit you

suggested harder and I'll return tomorrow.

Linux 3.16.0-00409-gb8c0aa4: Shuffling Zombie Juror
http://www.youtube.com/DanielFragaBR
http://exchangewar.info
Bitcoin: 12H6661yoLDUZaYPdah6urZS5WiXwTAUgL

Makes sense, but ...

wouldn't marking a bad commit "good" cause you to not see a *good* kernel again? Marking it "good" would seem push the search away from the bug toward the current "bad" commit.

Yes, you're right.

The "long series of 'good'" at the end actually implies that the last 'bad' is questionable - just marking a bad kernel as being good should push us further into 'bad' land, not the other way around. While marking a 'good' kernel as 'bad' will push us into 'bug hasn't happaned yet' land.

Which is somewhat odd, because the bad kernels should be easy to spot. But it could happen if screwing up the test (by not booting the right kernel, for example.

Or - and this is the scary part, and one of the huge downsides of 'git bisect' - it just ends up meaning that the bug comes and goes and is not quite repeatable enough.

Anyway, Dâniel, if you restart the bisection today, start it one kernel earlier: re-test the last 'bad' kernel too. So start with reconfirming that the c9b88e958182 kernel was bad (that *might* be as easy as just checking your old kernel boot logs, and verifying that "yes, I really booted it, and yes, it clearly hung and I had to hard-reboot into it")

Linus

Linus, today it's your lucky day, because I think I found the
real bad commit (if it isn't, then it's some very close to it). I managed to narrow the bisect and here's the result:

fd2ac4f4a65a7f34b0bc6433fcca1192d7ba8b8e is the first bad commit commit fd2ac4f4a65a7f34b0bc6433fcca1192d7ba8b8e

Author: Frederic Weisbecker <[email protected]>
Date:   Tue Mar 18 21:12:53 2014 +0100

nohz: Use nohz own full kick on 2nd task enqueue

Now that we have a nohz full remote kick based on irq work, lets use it to notify a CPU that it's exiting single task mode.

This unbloats a bit the scheduler IPI that the nohz code was abusing for its cool "callable anywhere/anytime" properties.

:040000 040000 5aa326eb5686b9343b56ab5d5e6779a0b988759d
3422b684c6d9121b888360789405050d0cf3cfdf M kernel

****************************************************************

And there's a nice Call Trace too:

Dec  4 06:03:33 tux kernel: [  737.180406] INFO: rcu_preempt detected stalls on CPUs/tasks: { 3} (detected by 4, t=240007 jiffies, g=36360, c=36359, q=0)
Dec  4 06:03:33 tux kernel: [  737.180412] sending NMI to all CPUs:
Dec  4 06:03:33 tux kernel: [  737.180416] NMI backtrace for cpu 4
Dec  4 06:03:34 tux kernel: [  737.180419] CPU: 4 PID: 785 Comm: kwin Not tainted 3.16.0-rc1-00005-gfd2ac4f #11
Dec  4 06:03:34 tux kernel: [  737.180420] Hardware name: System manufacturer System Product Name/P8Z68-V PRO GEN3, BIOS 3603 11/09/2012
Dec  4 06:03:34 tux kernel: [  737.180422] task: ffff880215360780 ti: ffff88020630c000 task.ti: ffff88020630c000
Dec  4 06:03:34 tux kernel: [  737.180423] RIP: 0010:[<ffffffff811fec10>]  [<ffffffff811fec10>] __const_udelay+0x0/0x30
Dec  4 06:03:34 tux kernel: [  737.180429] RSP: 0000:ffff88021f303e08  EFLAGS: 00000086
Dec  4 06:03:34 tux kernel: [  737.180430] RAX: 0000000000000c00 RBX: 0000000000002710 RCX: 0000000000000006
Dec  4 06:03:34 tux kernel: [  737.180431] RDX: 0000000000000007 RSI: 0000000000000046 RDI: 0000000000418958
Dec  4 06:03:34 tux kernel: [  737.180433] RBP: ffff88021f303e18 R08: 00000000000005cb R09: 00000000000005cb
Dec  4 06:03:34 tux kernel: [  737.180434] R10: 00000268d4b0862d R11: 00000000000005ca R12: ffffffff814f9680
Dec  4 06:03:34 tux kernel: [  737.180435] R13: ffffffff81521bd8 R14: ffffffff814f9680 R15: 0000000000000004
Dec  4 06:03:34 tux kernel: [  737.180437] FS:  00007fe9f003a900(0000) GS:ffff88021f300000(0000) knlGS:0000000000000000
Dec  4 06:03:34 tux kernel: [  737.180438] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Dec  4 06:03:34 tux kernel: [  737.180439] CR2: 00007fe93ba00000 CR3: 000000020635f000 CR4: 00000000000407e0
Dec  4 06:03:34 tux kernel: [  737.180440] Stack:
Dec  4 06:03:34 tux kernel: [  737.180441]  ffffffff8102f759 ffff88021f30d240 ffff88021f303e70 ffffffff8108dd41
Dec  4 06:03:34 tux kernel: [  737.180444]  ffffffff814f9680 ffffffff00000003 0000000000000000 0000000000000001
Dec  4 06:03:34 tux kernel: [  737.180445]  ffff880215360780 0000000000000000 0000000000000004 ffffffff81097730
Dec  4 06:03:34 tux kernel: [  737.180447] Call Trace:
Dec  4 06:03:34 tux kernel: [  737.180449]  <IRQ> 
Dec  4 06:03:34 tux kernel: [  737.180450]  [<ffffffff8102f759>] ? arch_trigger_all_cpu_backtrace+0x59/0x80
Dec  4 06:03:34 tux kernel: [  737.180457]  [<ffffffff8108dd41>] rcu_check_callbacks+0x6d1/0x740
Dec  4 06:03:35 tux kernel: [  737.180460]  [<ffffffff81097730>] ? tick_sched_handle.isra.20+0x40/0x40
Dec  4 06:03:35 tux kernel: [  737.180462]  [<ffffffff8104dea2>] update_process_times+0x42/0x70
Dec  4 06:03:35 tux kernel: [  737.180464]  [<ffffffff81097721>] tick_sched_handle.isra.20+0x31/0x40
Dec  4 06:03:35 tux kernel: [  737.180467]  [<ffffffff81097769>] tick_sched_timer+0x39/0x60
Dec  4 06:03:35 tux kernel: [  737.180469]  [<ffffffff810636a1>] __run_hrtimer.isra.33+0x41/0xd0
Dec  4 06:03:35 tux kernel: [  737.180472]  [<ffffffff81063a4f>] hrtimer_interrupt+0xef/0x250
Dec  4 06:03:35 tux kernel: [  737.180475]  [<ffffffff8102db65>] local_apic_timer_interrupt+0x35/0x60
Dec  4 06:03:35 tux kernel: [  737.180476]  [<ffffffff8102e12a>] smp_apic_timer_interrupt+0x3a/0x50
Dec  4 06:03:35 tux kernel: [  737.180480]  [<ffffffff81391a3a>] apic_timer_interrupt+0x6a/0x70
Dec  4 06:03:35 tux kernel: [  737.180481]  <EOI> 
Dec  4 06:03:35 tux kernel: [  737.180482]  [<ffffffff8109c4c6>] ? smp_call_function_many+0x256/0x270
Dec  4 06:03:35 tux kernel: [  737.180487]  [<ffffffff810c3290>] ? drain_pages+0x90/0x90
Dec  4 06:03:35 tux kernel: [  737.180489]  [<ffffffff810c3290>] ? drain_pages+0x90/0x90
Dec  4 06:03:35 tux kernel: [  737.180491]  [<ffffffff8109c5dc>] on_each_cpu_mask+0x2c/0x70
Dec  4 06:03:35 tux kernel: [  737.180493]  [<ffffffff810c0978>] drain_all_pages+0xb8/0xd0
Dec  4 06:03:35 tux kernel: [  737.180495]  [<ffffffff810c48a9>] __alloc_pages_nodemask+0x699/0x9f0
Dec  4 06:03:35 tux kernel: [  737.180498]  [<ffffffff810f84a2>] alloc_pages_vma+0x72/0x130
Dec  4 06:03:35 tux kernel: [  737.180501]  [<ffffffff8110579d>] do_huge_pmd_anonymous_page+0xed/0x3b0
Dec  4 06:03:35 tux kernel: [  737.180503]  [<ffffffff810e1721>] handle_mm_fault+0x141/0xae0
Dec  4 06:03:35 tux kernel: [  737.180506]  [<ffffffff810e6149>] ? vma_merge+0xf9/0x370
Dec  4 06:03:36 tux kernel: [  737.180508]  [<ffffffff81037f37>] __do_page_fault+0x167/0x4c0
Dec  4 06:03:36 tux kernel: [  737.180510]  [<ffffffff810e7e24>] ? do_mmap_pgoff+0x2e4/0x3d0
Dec  4 06:03:36 tux kernel: [  737.180513]  [<ffffffff8106f205>] ? local_clock+0x25/0x30
Dec  4 06:03:36 tux kernel: [  737.180516]  [<ffffffff8106fa5f>] ? vtime_account_user+0x4f/0x60
Dec  4 06:03:36 tux kernel: [  737.180517]  [<ffffffff810382ce>] do_page_fault+0x1e/0x70
Dec  4 06:03:36 tux kernel: [  737.180520]  [<ffffffff813921c2>] page_fault+0x22/0x30
Dec  4 06:03:36 tux kernel: [  737.180521] Code: 66 66 2e 0f 1f 84 00 00 00 00 00 48 ff c8 75 fb 48 ff c8 5d c3 66 0f 1f 44 00 00 55 48 89 e5 ff 15 2e 61 30 00 5d c3 0f 1f 40 00 <55> 48 8d 04 bd 00 00 00 00 48 89 e5 65 48 8b 14 25 20 12 01 00 
Dec  4 06:03:36 tux kernel: [  737.180542] NMI backtrace for cpu 6
Dec  4 06:03:36 tux kernel: [  737.180545] CPU: 6 PID: 8441 Comm: sh Not tainted 3.16.0-rc1-00005-gfd2ac4f #11
Dec  4 06:03:36 tux kernel: [  737.180547] Hardware name: System manufacturer System Product Name/P8Z68-V PRO GEN3, BIOS 3603 11/09/2012
Dec  4 06:03:36 tux kernel: [  737.180548] task: ffff8800c93d7800 ti: ffff880202094000 task.ti: ffff880202094000
Dec  4 06:03:36 tux kernel: [  737.180550] RIP: 0033:[<00007fcbfadb200f>]  [<00007fcbfadb200f>] 0x7fcbfadb200f
Dec  4 06:03:36 tux kernel: [  737.180563] RSP: 002b:00007fffa287e200  EFLAGS: 00000206
Dec  4 06:03:36 tux kernel: [  737.180564] RAX: 00007fffa287e2f0 RBX: 00007fffa287e2d0 RCX: 000000000095200f
Dec  4 06:03:36 tux kernel: [  737.180565] RDX: 0000000000000001 RSI: 00007fffa287e2f0 RDI: 00007fcbfb12f8a0
Dec  4 06:03:36 tux kernel: [  737.180567] RBP: 000000000095200e R08: 0000000000000000 R09: 00007fffa287e2e0
Dec  4 06:03:36 tux kernel: [  737.180568] R10: 000000000095200d R11: 0000000000000000 R12: 000000000095200f
Dec  4 06:03:36 tux kernel: [  737.180569] R13: 00007fffa287e2e8 R14: 000000000095200f R15: 0000000000000006
Dec  4 06:03:36 tux kernel: [  737.180571] FS:  00007fcbfb728700(0000) GS:ffff88021f380000(0000) knlGS:0000000000000000
Dec  4 06:03:36 tux kernel: [  737.180572] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Dec  4 06:03:36 tux kernel: [  737.180573] CR2: 0000000000a91000 CR3: 00000001fdfbe000 CR4: 00000000000407e0
Dec  4 06:03:37 tux kernel: [  737.180574] 
Dec  4 06:03:37 tux kernel: [  737.180576] NMI backtrace for cpu 7
Dec  4 06:03:37 tux kernel: [  737.180579] CPU: 7 PID: 8427 Comm: cc1 Not tainted 3.16.0-rc1-00005-gfd2ac4f #11
Dec  4 06:03:37 tux kernel: [  737.180580] Hardware name: System manufacturer System Product Name/P8Z68-V PRO GEN3, BIOS 3603 11/09/2012
Dec  4 06:03:37 tux kernel: [  737.180582] task: ffff8802048ec380 ti: ffff880204b48000 task.ti: ffff880204b48000
Dec  4 06:03:37 tux kernel: [  737.180583] RIP: 0033:[<0000000000ad9689>]  [<0000000000ad9689>] 0xad9689
Dec  4 06:03:37 tux kernel: [  737.180589] RSP: 002b:00007fffd63b4180  EFLAGS: 00000297
Dec  4 06:03:37 tux kernel: [  737.180590] RAX: 0000000000000059 RBX: 00007f78fe6811b0 RCX: 0000000000000000
Dec  4 06:03:37 tux kernel: [  737.180591] RDX: 0000000000000003 RSI: 0000000000000072 RDI: 00007f78fe6811b0
Dec  4 06:03:37 tux kernel: [  737.180593] RBP: 00007f78fe6811b0 R08: 0000000000000001 R09: 0000000000000000
Dec  4 06:03:37 tux kernel: [  737.180594] R10: 0000000000000000 R11: 0000000000000003 R12: 00000000015f50fa
Dec  4 06:03:37 tux kernel: [  737.180595] R13: 0000000000000000 R14: 0000000000000ba4 R15: 00007f78fe680a20
Dec  4 06:03:37 tux kernel: [  737.180597] FS:  00007f79008f8880(0000) GS:ffff88021f3c0000(0000) knlGS:0000000000000000
Dec  4 06:03:37 tux kernel: [  737.180598] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Dec  4 06:03:37 tux kernel: [  737.180599] CR2: 00007f78fe693000 CR3: 0000000204924000 CR4: 00000000000407e0
Dec  4 06:03:37 tux kernel: [  737.180600] 
Dec  4 06:03:37 tux kernel: [  737.180601] NMI backtrace for cpu 0
Dec  4 06:03:37 tux kernel: [  737.180604] CPU: 0 PID: 29099 Comm: cc1 Not tainted 3.16.0-rc1-00005-gfd2ac4f #11
Dec  4 06:03:37 tux kernel: [  737.180605] Hardware name: System manufacturer System Product Name/P8Z68-V PRO GEN3, BIOS 3603 11/09/2012
Dec  4 06:03:37 tux kernel: [  737.180606] task: ffff8800035e0780 ti: ffff8800035ec000 task.ti: ffff8800035ec000
Dec  4 06:03:37 tux kernel: [  737.180607] RIP: 0033:[<00000000006b1df2>]  [<00000000006b1df2>] 0x6b1df2
Dec  4 06:03:38 tux kernel: [  737.180611] RSP: 002b:00007fffbbb506f0  EFLAGS: 00000202
Dec  4 06:03:38 tux kernel: [  737.180613] RAX: 000000000329e508 RBX: 0000000002f1d888 RCX: 0000000002f1d8e8
Dec  4 06:03:38 tux kernel: [  737.180614] RDX: 000000000329e538 RSI: 0000000000000000 RDI: 0000000002f1d888
Dec  4 06:03:38 tux kernel: [  737.180615] RBP: 0000000003088008 R08: 000000000329e568 R09: 0000000000000000
Dec  4 06:03:38 tux kernel: [  737.180616] R10: 00000000ffffffff R11: 00000000ffffffff R12: 0000000002f1d2b8
Dec  4 06:03:38 tux kernel: [  737.180617] R13: 0000000003266ba8 R14: 0000000000000001 R15: 00007f72248ac3b8
Dec  4 06:03:38 tux kernel: [  737.180619] FS:  00007f72297ee880(0000) GS:ffff88021f200000(0000) knlGS:0000000000000000
Dec  4 06:03:38 tux kernel: [  737.180620] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Dec  4 06:03:38 tux kernel: [  737.180621] CR2: 00007f72215d5e28 CR3: 0000000012d96000 CR4: 00000000000407f0
Dec  4 06:03:38 tux kernel: [  737.180622] 
Dec  4 06:03:38 tux kernel: [  737.180623] NMI backtrace for cpu 1
Dec  4 06:03:38 tux kernel: [  737.180626] CPU: 1 PID: 7864 Comm: cc1 Not tainted 3.16.0-rc1-00005-gfd2ac4f #11
Dec  4 06:03:38 tux kernel: [  737.180631] Hardware name: System manufacturer System Product Name/P8Z68-V PRO GEN3, BIOS 3603 11/09/2012
Dec  4 06:03:38 tux kernel: [  737.180635] task: ffff88020443e900 ti: ffff880203f80000 task.ti: ffff880203f80000
Dec  4 06:03:38 tux kernel: [  737.180638] RIP: 0033:[<00007f90422909df>]  [<00007f90422909df>] 0x7f90422909df
Dec  4 06:03:38 tux kernel: [  737.180648] RSP: 002b:00007fff76432930  EFLAGS: 00000246
Dec  4 06:03:38 tux kernel: [  737.180652] RAX: 00007f90425bb678 RBX: 000000000185f6e0 RCX: 0000000000000440
Dec  4 06:03:38 tux kernel: [  737.180655] RDX: 00007f90425bb678 RSI: 0000000000000000 RDI: 00007f90425bb620
Dec  4 06:03:38 tux kernel: [  737.180660] RBP: 0000000000000400 R08: 00007f904201bae0 R09: 000000000189f130
Dec  4 06:03:38 tux kernel: [  737.180663] R10: 0000000000000000 R11: 0000000000000001 R12: 00007f90425bb620
Dec  4 06:03:38 tux kernel: [  737.180665] R13: 000000000185f7b0 R14: 0000000000000330 R15: 0000000000000000
Dec  4 06:03:38 tux kernel: [  737.180667] FS:  00007f9043b24880(0000) GS:ffff88021f240000(0000) knlGS:0000000000000000
Dec  4 06:03:38 tux kernel: [  737.180668] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Dec  4 06:03:39 tux kernel: [  737.180669] CR2: 00007f903faec000 CR3: 000000010499d000 CR4: 00000000000407e0
Dec  4 06:03:39 tux kernel: [  737.180670] 
Dec  4 06:03:39 tux kernel: [  737.180672] NMI backtrace for cpu 2
Dec  4 06:03:39 tux kernel: [  737.180674] CPU: 2 PID: 587 Comm: X Not tainted 3.16.0-rc1-00005-gfd2ac4f #11
Dec  4 06:03:39 tux kernel: [  737.180679] Hardware name: System manufacturer System Product Name/P8Z68-V PRO GEN3, BIOS 3603 11/09/2012
Dec  4 06:03:39 tux kernel: [  737.180683] task: ffff880215367080 ti: ffff88021391c000 task.ti: ffff88021391c000
Dec  4 06:03:39 tux kernel: [  737.180685] RIP: 0033:[<00007f93727697c2>]  [<00007f93727697c2>] 0x7f93727697c2
Dec  4 06:03:39 tux kernel: [  737.180694] RSP: 002b:00007fff5cb41b80  EFLAGS: 00003246
Dec  4 06:03:39 tux kernel: [  737.180696] RAX: 0000000000000021 RBX: 0000000000000001 RCX: 00007f9372a94620
Dec  4 06:03:39 tux kernel: [  737.180697] RDX: 0000000000000000 RSI: 00000000021abd90 RDI: 00007f9372a94620
Dec  4 06:03:39 tux kernel: [  737.180698] RBP: 00000000021abda0 R08: 0000000000000000 R09: 0000000000000000
Dec  4 06:03:39 tux kernel: [  737.180700] R10: 0000000000864d80 R11: 0000000000000000 R12: 000000000183a440
Dec  4 06:03:39 tux kernel: [  737.180701] R13: 0000000001b83b10 R14: 000000000086daf0 R15: 000000000085f078
Dec  4 06:03:39 tux kernel: [  737.180702] FS:  00007f93760ec880(0000) GS:ffff88021f280000(0000) knlGS:0000000000000000
Dec  4 06:03:39 tux kernel: [  737.180704] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Dec  4 06:03:39 tux kernel: [  737.180705] CR2: 00007f46a794c000 CR3: 0000000214aeb000 CR4: 00000000000407e0
Dec  4 06:03:39 tux kernel: [  737.180706] 
Dec  4 06:03:39 tux kernel: [  737.180708] NMI backtrace for cpu 5
Dec  4 06:03:39 tux kernel: [  737.180710] CPU: 5 PID: 8163 Comm: cc1 Not tainted 3.16.0-rc1-00005-gfd2ac4f #11
Dec  4 06:03:39 tux kernel: [  737.180711] Hardware name: System manufacturer System Product Name/P8Z68-V PRO GEN3, BIOS 3603 11/09/2012
Dec  4 06:03:39 tux kernel: [  737.180713] task: ffff8801afd8d280 ti: ffff8801aff20000 task.ti: ffff8801aff20000
Dec  4 06:03:39 tux kernel: [  737.180714] RIP: 0033:[<00000000006b1ce8>]  [<00000000006b1ce8>] 0x6b1ce8
Dec  4 06:03:39 tux kernel: [  737.180718] RSP: 002b:00007fff3e67c270  EFLAGS: 00000246
Dec  4 06:03:40 tux kernel: [  737.180719] RAX: 00000000032530f8 RBX: 00000000032be448 RCX: 0000000000000000
Dec  4 06:03:40 tux kernel: [  737.180720] RDX: 00000000000000c7 RSI: 0000000003253128 RDI: 00000000032e7ec0
Dec  4 06:03:40 tux kernel: [  737.180722] RBP: 00000000032be488 R08: 00000000ffffffff R09: 0000000000000000
Dec  4 06:03:40 tux kernel: [  737.180723] R10: 0000000000000000 R11: 00000000fffffffe R12: 0000000000000001
Dec  4 06:03:40 tux kernel: [  737.180724] R13: 0000000000000000 R14: 00000000032be448 R15: 0000000003227358
Dec  4 06:03:40 tux kernel: [  737.180725] FS:  00007f3b1ed4b880(0000) GS:ffff88021f340000(0000) knlGS:0000000000000000
Dec  4 06:03:40 tux kernel: [  737.180727] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Dec  4 06:03:40 tux kernel: [  737.180728] CR2: 00007f3b1bd32000 CR3: 0000000137da8000 CR4: 00000000000407e0
Dec  4 06:03:40 tux kernel: [  737.180729] 
Dec  4 06:03:40 tux kernel: [  737.180730] NMI backtrace for cpu 3
Dec  4 06:03:40 tux kernel: [  737.180733] CPU: 3 PID: 18986 Comm: cc1 Not tainted 3.16.0-rc1-00005-gfd2ac4f #11
Dec  4 06:03:40 tux kernel: [  737.180734] Hardware name: System manufacturer System Product Name/P8Z68-V PRO GEN3, BIOS 3603 11/09/2012
Dec  4 06:03:40 tux kernel: [  737.180736] task: ffff8801af0fad00 ti: ffff88019d734000 task.ti: ffff88019d734000
Dec  4 06:03:40 tux kernel: [  737.180737] RIP: 0010:[<ffffffff8106378c>]  [<ffffffff8106378c>] hrtimer_try_to_cancel+0x5c/0x80
Dec  4 06:03:40 tux kernel: [  737.180740] RSP: 0000:ffff88021f2c3da0  EFLAGS: 00000002
Dec  4 06:03:40 tux kernel: [  737.180741] RAX: ffff88021f2ccf80 RBX: ffff88021f2cda80 RCX: 0000000000000058
Dec  4 06:03:40 tux kernel: [  737.180742] RDX: 0000000000000002 RSI: 000000000000006a RDI: ffff88021f2ccf40
Dec  4 06:03:40 tux kernel: [  737.180744] RBP: ffff88021f2c3db8 R08: 0000000000000df2 R09: 00000000000000ee
Dec  4 06:03:41 tux kernel: [  737.180745] R10: 0000000000000003 R11: 0000000000000020 R12: 00000000ffffffff
Dec  4 06:03:41 tux kernel: [  737.180746] R13: 0000000000000000 R14: 0000000000000003 R15: ffff88021f2ccf40
Dec  4 06:03:41 tux kernel: [  737.180748] FS:  00007ff8b2464880(0000) GS:ffff88021f2c0000(0000) knlGS:0000000000000000
Dec  4 06:03:41 tux kernel: [  737.180749] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Dec  4 06:03:41 tux kernel: [  737.180750] CR2: 00007f9151c00000 CR3: 00000001e70f7000 CR4: 00000000000407e0
Dec  4 06:03:41 tux kernel: [  737.180751] Stack:
Dec  4 06:03:41 tux kernel: [  737.180752]  0000000000000082 ffff88021f2cda80 000000738285228a ffff88021f2c3dd0
Dec  4 06:03:41 tux kernel: [  737.180755]  ffffffff810637ca ffff88021f2cda80 ffff88021f2c3df0 ffffffff81097842
Dec  4 06:03:41 tux kernel: [  737.180757]  ffff88021f2cda80 000000738285228a ffff88021f2c3e10 ffffffff81097c4f
Dec  4 06:03:41 tux kernel: [  737.180759] Call Trace:
Dec  4 06:03:41 tux kernel: [  737.180760]  <IRQ> 
Dec  4 06:03:41 tux kernel: [  737.180761]  [<ffffffff810637ca>] hrtimer_cancel+0x1a/0x30
Dec  4 06:03:41 tux kernel: [  737.180766]  [<ffffffff81097842>] tick_nohz_restart+0x12/0x80
Dec  4 06:03:41 tux kernel: [  737.180769]  [<ffffffff81097c4f>] __tick_nohz_full_check+0x9f/0xb0
Dec  4 06:03:41 tux kernel: [  737.180771]  [<ffffffff81097c69>] nohz_full_kick_work_func+0x9/0x10
Dec  4 06:03:41 tux kernel: [  737.180774]  [<ffffffff810aecd4>] irq_work_run_list+0x44/0x70
Dec  4 06:03:41 tux kernel: [  737.180777]  [<ffffffff81097730>] ? tick_sched_handle.isra.20+0x40/0x40
Dec  4 06:03:41 tux kernel: [  737.180779]  [<ffffffff810aed19>] __irq_work_run+0x19/0x30
Dec  4 06:03:41 tux kernel: [  737.180782]  [<ffffffff810aed98>] irq_work_run+0x18/0x40
Dec  4 06:03:41 tux kernel: [  737.180784]  [<ffffffff8104deb6>] update_process_times+0x56/0x70
Dec  4 06:03:41 tux kernel: [  737.180786]  [<ffffffff81097721>] tick_sched_handle.isra.20+0x31/0x40
Dec  4 06:03:42 tux kernel: [  737.180788]  [<ffffffff81097769>] tick_sched_timer+0x39/0x60
Dec  4 06:03:42 tux kernel: [  737.180790]  [<ffffffff810636a1>] __run_hrtimer.isra.33+0x41/0xd0
Dec  4 06:03:42 tux kernel: [  737.180792]  [<ffffffff81063a4f>] hrtimer_interrupt+0xef/0x250
Dec  4 06:03:42 tux kernel: [  737.180795]  [<ffffffff8102db65>] local_apic_timer_interrupt+0x35/0x60
Dec  4 06:03:42 tux kernel: [  737.180797]  [<ffffffff8102e12a>] smp_apic_timer_interrupt+0x3a/0x50
Dec  4 06:03:42 tux kernel: [  737.180799]  [<ffffffff81391a3a>] apic_timer_interrupt+0x6a/0x70
Dec  4 06:03:42 tux kernel: [  737.180800]  <EOI> 
Dec  4 06:03:42 tux kernel: [  737.180802] Code: 2a 48 c7 c1 40 cf 00

00 65 48 03 0c 25 c8 cd 00 00 48 39 08 48 89 c6 48 89 df 41 b4 01 0f 94 c1 83 e2 02 0f b6 c9 e8 84 f8 ff ff <48> 8b 43 30 48 8b 75 e8 48 8b 38 e8 34 cb 32 00 48 83 c4 08 44

***************************************************

And here it's the bisect log:

git bisect start
# good: [19583ca584d6f574384e17fe7613dfaeadcdc4a6] Linux 3.16
git bisect good 19583ca584d6f574384e17fe7613dfaeadcdc4a6
# bad: [e9c9eecabaa898ff3fedd98813ee4ac1a00d006a] Merge branch 'x86-cpufeature-for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip
git bisect bad e9c9eecabaa898ff3fedd98813ee4ac1a00d006a
# good: [c9b88e9581828bb8bba06c5e7ee8ed1761172b6e] Merge tag 'trace-3.17-2' of git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace
git bisect good c9b88e9581828bb8bba06c5e7ee8ed1761172b6e
# good: [5bda4f638f36ef4c4e3b1397b02affc3db94356e] Merge branch 'core-rcu-for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip
git bisect good 5bda4f638f36ef4c4e3b1397b02affc3db94356e
# good: [288be943b5024729cd6809b61b62f727960178f3] perf tools: Add dso__data_status_seen()
git bisect good 288be943b5024729cd6809b61b62f727960178f3
# good: [ef35ad26f8ff44d2c93e29952cdb336bda729d9d] Merge branch 'perf-core-for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip
git bisect good ef35ad26f8ff44d2c93e29952cdb336bda729d9d
# bad: [b728ca06029d085a1585c1926610f26de93b9146] sched: Rework check_for_tasks()
git bisect bad b728ca06029d085a1585c1926610f26de93b9146
# bad: [541b82644d72c1ef4a0587515a619712c1c19bd3] sched/core: Fix formatting issues in sched_can_stop_tick()
git bisect bad 541b82644d72c1ef4a0587515a619712c1c19bd3
# bad: [3882ec643997757824cd5f25180cd8a787b9dbe1] nohz: Use IPI implicit full barrier against rq->nr_running r/w
git bisect bad 3882ec643997757824cd5f25180cd8a787b9dbe1
# good: [3d36aebc2e78923095575df954f3f3b430ac0a30] nohz: Support nohz full remote kick
git bisect good 3d36aebc2e78923095575df954f3f3b430ac0a30
# bad: [fd2ac4f4a65a7f34b0bc6433fcca1192d7ba8b8e] nohz: Use nohz own full kick on 2nd task enqueue
git bisect bad fd2ac4f4a65a7f34b0bc6433fcca1192d7ba8b8e
# good: [53c5fa16b4c843f1df91f7498e3c7bf95e0eaefa] nohz: Switch to nohz full remote kick on timer enqueue
git bisect good 53c5fa16b4c843f1df91f7498e3c7bf95e0eaefa

# first bad commit: [fd2ac4f4a65a7f34b0bc6433fcca1192d7ba8b8e] nohz:
Use nohz own full kick on 2nd task enqueue

	**************

	I hope it's correct now! If you need more testing don't 

hesitate to ask ;)

Ps: I have the Call traces for the other bad commits, if it's needed.

Linux 3.16.0-rc1-00004-g53c5fa1: Shuffling Zombie Juror
http://www.youtube.com/DanielFragaBR
http://exchangewar.info
Bitcoin: 12H6661yoLDUZaYPdah6urZS5WiXwTAUgL

Ok, that actually looks very reasonable, I had actually looked at it because of the whole "changes IPI" thing.

One more thing to try: does a revert fix it on current git?

It doesn't revert entirely cleanly, but close enough - attached a quick rough patch that may or may not work, but looks like a good revert.

Dave - this might be worth testing for you too, exactly because of that whole "it changes how we do IPI's". It was your bug report with TLB IPI's that made me look at that commit originally.

Linus

---

 kernel/sched/core.c  | 5 ++++-
 kernel/sched/sched.h | 2 +-
 2 files changed, 5 insertions(+), 2 deletions(-)

index 89e7283015a6..1b40aed13931 100644
@@ -1577,7 +1577,9 @@ void scheduler_ipi(void)
 	 */
 	preempt_fold_need_resched();
 
-	if (llist_empty(&this_rq()->wake_list) && !got_nohz_idle_kick())
+	if (llist_empty(&this_rq()->wake_list)
+			&& !tick_nohz_full_cpu(smp_processor_id())
+			&& !got_nohz_idle_kick())
 		return;
 
 	/*

@@ -1594,6 +1596,7 @@ void scheduler_ipi(void)
 	 * somewhat pessimize the simple resched case.
 	 */
 	irq_enter();
+	tick_nohz_full_check();
 	sched_ttwu_pending();
 
 	/*

index 2df8ef067cc5..e9a73143d318 100644
@@ -1245,7 +1245,7 @@ static inline void add_nr_running(struct rq *rq, unsigned count)
 			 * new value of rq->nr_running is visible on reception
 			 * from the target.
 			 */
-			tick_nohz_full_kick_cpu(rq->cpu);
+			smp_send_reschedule(rq->cpu);
 		}
 #endif
 	}

I think this is a different issue. What Daniel reported is:

Dec  4 06:03:41 tux kernel: [  737.180761]  [<ffffffff810637ca>] hrtimer_cancel+0x1a/0x30
Dec  4 06:03:41 tux kernel: [  737.180766]  [<ffffffff81097842>] tick_nohz_restart+0x12/0x80
Dec  4 06:03:41 tux kernel: [  737.180769]  [<ffffffff81097c4f>] __tick_nohz_full_check+0x9f/0xb0
Dec  4 06:03:41 tux kernel: [  737.180771]  [<ffffffff81097c69>] nohz_full_kick_work_func+0x9/0x10
Dec  4 06:03:41 tux kernel: [  737.180774]  [<ffffffff810aecd4>] irq_work_run_list+0x44/0x70
Dec  4 06:03:41 tux kernel: [  737.180777]  [<ffffffff81097730>] ? tick_sched_handle.isra.20+0x40/0x40
Dec  4 06:03:41 tux kernel: [  737.180779]  [<ffffffff810aed19>] __irq_work_run+0x19/0x30
Dec  4 06:03:41 tux kernel: [  737.180782]  [<ffffffff810aed98>] irq_work_run+0x18/0x40
Dec  4 06:03:41 tux kernel: [  737.180784]  [<ffffffff8104deb6>] update_process_times+0x56/0x70
Dec  4 06:03:41 tux kernel: [  737.180786]  [<ffffffff81097721>] tick_sched_handle.isra.20+0x31/0x40
Dec  4 06:03:42 tux kernel: [  737.180788]  [<ffffffff81097769>] tick_sched_timer+0x39/0x60
Dec  4 06:03:42 tux kernel: [  737.180790]  [<ffffffff810636a1>] __run_hrtimer.isra.33+0x41/0xd0
Dec  4 06:03:42 tux kernel: [  737.180792]  [<ffffffff81063a4f>] hrtimer_interrupt+0xef/0x250
Dec  4 06:03:42 tux kernel: [  737.180795]  [<ffffffff8102db65>] local_apic_timer_interrupt+0x35/0x60
Dec  4 06:03:42 tux kernel: [  737.180797]  [<ffffffff8102e12a>] smp_apic_timer_interrupt+0x3a/0x50
Dec  4 06:03:42 tux kernel: [  737.180799]  [<ffffffff81391a3a>] apic_timer_interrupt+0x6a/0x70

And this bug has been fixed upstream with:

_ nohz: nohz full depends on irq work self IPI support _ x86: Tell irq work about self IPI support
_ irq_work: Force raised irq work to run on irq work interrupt _ nohz: Move nohz full init call to tick init

These patches have been backported to stable as well.

I suspect Daniel rewinded far enough to fall on that old bug.

Daniel, did you see the above very stacktrace in latest upstream too? Or was it a different one?

You're completely right Frederic. I was so obsessed with v3.17
that I forgot to check the fixes made after v3.17 (shame on me!).

The revert patch Linus provided fixes the issue with v3.17, but
since Frederic just confirmed it was fixed after v3.17, then it doesn't matter anymore.

Sorry about that Linus. Well, so I'm using 3.18.0-rc7 and
everything is working perfect here. :)

Thank you.

Linux 3.18.0-rc7: Diseased Newt
http://www.youtube.com/DanielFragaBR
http://exchangewar.info
Bitcoin: 12H6661yoLDUZaYPdah6urZS5WiXwTAUgL

Ok. Can you make sure to really beat on that kernel, just to make sure there's nothing else hiding?

Linus

Yes, I'll keep torturing this kernel. If I find something, I'll
report here, but so far, no problem at all.

Linux 3.18.0-rc7: Diseased Newt
http://www.youtube.com/DanielFragaBR
http://exchangewar.info
Bitcoin: 12H6661yoLDUZaYPdah6urZS5WiXwTAUgL

Hello,

Yeap, keeping watch on the thread and working on a patch to dump more workqueue info on sysrq (I don't know which sysrq alphabet to hang it on yet, mostly likely it'd get appeneded to tasks dump). For all three subsystems, for-3.17 pulls contained quite a bit of changes. I've skimmed through the commits but nothing rings the bell - I've never seen this pattern of failures in any of the three subsystems. Maybe a subtle percpu bug or cpuset messing up scheduling somehow? Anyways, let's see how 47dfe4037 does.

Thanks.

tejun

Thank you!!!

Was this as difficult to trigger as the version with the Kconfig hack that used CONFIG_PREEMPT=y and CONFIG_TREE_PREEMPT_RCU=n?

Thanx, Paul

	;)

Yes. I had to try many times until I got the call trace.

I'll try the bisect as Linus suggested, but if you have any
other suggestions, just ask ;). Thanks Paul.

Linux 3.17.0-dirty: Shuffling Zombie Juror
http://www.youtube.com/DanielFragaBR
http://exchangewar.info
Bitcoin: 12H6661yoLDUZaYPdah6urZS5WiXwTAUgL

Sounds good to me -- getting a single commit somewhere between 3.16 and 3.17 is going to be a lot better than reasoning indirectly from some set of RCU read-side critical sections. ;-)

Thanx, Paul

To Linus's point, I guess I could look at the RCU CPU stall warning. ;-)

Summary: Not seeing something that would loop for 21 seconds. Dâniel, if you let this run, does it hit a second RCU CPU stall warning, or does it just lock up?

Details:

First, what would we be looking for? We know that with CONFIG_PREEMPT=n, things work, or at least that the failure rate is quite low. With CONFIG_PREEMPT=y, with or without CONFIG_TREE_PREEMPT_RCU=y, things can break. This is backwards of the usual behavior: Normally CONFIG_PREEMPT=y kernels are a bit less prone to RCU CPU stall warnings, at least assuming that the kernel spends a relatively small fraction of its time in RCU read-side critical sections.

So, how could this be?

1. Someone forgot an rcu_read_unlock() on one of the exit paths from
some RCU read-side critical section somewhere. This seems unlikely, but either CONFIG_PROVE_RCU=y or CONFIG_PREEMPT_DEBUG=y should catch it.

2. Someone forgot a preempt_enable() on one of the exit paths from
some preempt-disable region somewhere. This also seems a bit unlikely, but CONFIG_PREEMPT_DEBUG=y should catch it.

3. Preemption exposes a race condition that is extremely unlikely
for CONFIG_PREEMPT=n.

Of course, it wouldn't hurt for someone who knows mm better than I to check my work.

Note that the patch I gave to Dâniel provides only rcu_sched, as opposed to the usual CONFIG_PREEMPT=y rcu_preempt and rcu_sched. This is expected behavior for CONFIG_TREE_RCU=y/CONFIG_TREE_PREEMPT_RCU=n.

This does have a loop whose length is controlled by the "nr" argument.

This one is inconsistent with the release_pages() called function. Besides, its runtime is limited by the number of CPUs, so it shouldn't go on forever.

This one should also have a sharply limited runtime.

This one does acquire locks, so could in theory run for a long time. Would require high contention on ->lru_lock, though. A pvec can only contain 14 pages, so the move loop should have limited runtime.

This one contains a retry loop, at least if CONFIG_NUMA=y. But I don't see anything here that would block an RCU grace period.

Duplicate address above, presumably one or both are due to stack-trace confusion.

If this one had a problem, I would expect to see it in some of its called functions.

Ditto.

Ditto.

This one uses SRCU, not RCU.

These two don't call fsnotify(), so I am assuming that the stack trace is confused here. Any chance of enabling frame pointers or some such to get an accurate stack trace? (And yes, this is one CPU tracing another live CPU's stack, so some confusion is inherent, but probably not this far up the stack.)

Wrapper for __do_page_fault(). Yay! Functions that actually call each other in this stack trace! ;-)

Not seeing much in the way of loops here.

Thanx, Paul

It just lock up. I can't even use the keyboard or mouse, so I
have to hard reset the system.

I'm trying the bisect you asked... even if it takes longer,
maybe I can find something for you.

Linux 3.17.0-rc6-00235-gb94d525: Shuffling Zombie Juror
http://www.youtube.com/DanielFragaBR
http://exchangewar.info
Bitcoin: 12H6661yoLDUZaYPdah6urZS5WiXwTAUgL

So just to verify:

Without CONFIG_PREEMPT, things work well for you?

But with CONFIG_PREEMPT, you are able to create the rcu_sched stalls both with and without CONFIG_TREE_PREEMPT_RCU?

Correct?

Paul?

Linus

Yes.

Yes, correct. And without CONFIG_TREE_PREEMPT_RCU it's
much harder to trigger the bug.

Linux 3.17.0-dirty: Shuffling Zombie Juror
http://www.youtube.com/DanielFragaBR
http://exchangewar.info
Bitcoin: 12H6661yoLDUZaYPdah6urZS5WiXwTAUgL

It is needed at lest for testing.

CONFIG_TREE_PREEMPT_RCU=y with CONFIG_PREEMPT=n is needed for testing too.

Please enable them (or enable them under CONFIG_RCU_TRACE=y)

It is a really easy edit to Kconfig, but I don't want people using it in production because I really don't need the extra test scenarios. So I am happy to provide the patch below as needed, but not willing to submit it to mainline without a lot more justification. Because if it appears in mainline, people will start using it in production, whether I am doing proper testing of it or not. :-/

Thanx, Paul

------------------------------------------------------------------------

index 903505e66d1d..2cf71fcd514f 100644
@@ -469,7 +469,7 @@ choice
 
 config TREE_RCU
 	bool "Tree-based hierarchical RCU"
-	depends on !PREEMPT && SMP
+	depends on SMP
 	select IRQ_WORK
 	help
 	  This option selects the RCU implementation that is

Lai, sorry but I didn't understand. Do you mean both of them
enabled? Because how can CONFIG_TREE_PREEMPT_RCU be enabled without CONFIG_PREEMPT ?

If you mean both enabled, I already reported a call trace with
both enabled:

https://bugzilla.kernel.org/show_bug.cgi?id=85941

Please see my previous answer to Linus and Paul too.

Regarding CONFIG_RCU_TRACE, do you mean
"CONFIG_TREE_RCU_TRACE"? I couldn't find CONFIG_RCU_TRACE.

Thanks.

Linux 3.17.0-dirty: Shuffling Zombie Juror
http://www.youtube.com/DanielFragaBR
http://exchangewar.info
Bitcoin: 12H6661yoLDUZaYPdah6urZS5WiXwTAUgL

Hmmm... I did misread that in my reply. A similar Kconfig edit will enable that, but I am even less happy about the thought of pushing that to mainline! ;-)

Thanx, Paul

Sorry, I replied to Paul, and my reply was off-topic, it has nothing related your reports. Sorry again.

I think we need two combinations for testing (not mainline, but I think they (combinations) should be enabled for test farms).

So I hope Paul enable them (combinations).

combination1: CONFIG_TREE_PREEMPT_RCU=n & CONFIG_PREEMPT=y
combination2: CONFIG_TREE_PREEMPT_RCU=y & CONFIG_PREEMPT=n

The core code should work correctly in these combinations.
I agree with Paul that these combinations should not be enabled in production, So my request is: enable these combinations under CONFIG_RCU_TRACE or CONFIG_TREE_RCU_TRACE.

For myself, I always edit the Kconfig directly, thus it is not a problem for me. But there is no way for test farms to test these combinations.

Thanks,
Lai

OK, I'll bite...

How have these two combinations helped you in your testing?

The reason I ask is that I am actually trying to -decrease- the RCU configurations, not increase them. Added configurations need to have strong justification, for example, the kernel-tracing/patching need for tasks_rcu.

Thanx, Paul

Yeah, the watchdog code is very chatty during thread 'unparking'. If Dave's dmesg log isn't seeing any:

"enabled on all CPUs, permanently consumes one hw-PMU counter"

except on boot, then I believe the park/unpark race you see shouldn't be occuring in this scenario.

Well we can explore this route..

I added a patch below that just logs the watchdog timer function and kernel thread for each cpu. It's a little chatty but every 4 seconds you will see something like this in the logs:

[ 2507.580184] 1: watchdog process kicked (reset)
[ 2507.581154] 0: watchdog process kicked (reset)
[ 2507.581172] 0: watchdog run
[ 2507.593469] 1: watchdog run
[ 2507.595106] 2: watchdog process kicked (reset)
[ 2507.595120] 2: watchdog run
[ 2507.608136] 3: watchdog process kicked (reset)
[ 2507.613204] 3: watchdog run

With the printk timestamps it would be interesting to see what the watchdog was doing in its final moments and if the timestamps verify the exceeded duration or if the watchdog screws up the calculation and falsely reports a lockup.

Cheers,
Don

index 70bf118..b1ea06c 100644
@@ -324,6 +324,7 @@ static enum hrtimer_restart watchdog_timer_fn(struct hrtimer *hrtimer)
 	hrtimer_forward_now(hrtimer, ns_to_ktime(sample_period));
 
 	if (touch_ts == 0) {
+		printk("%d: watchdog process kicked (reset)\n", smp_processor_id());
 		if (unlikely(__this_cpu_read(softlockup_touch_sync))) {
 			/*
 			 * If the time stamp was touched atomically

@@ -346,6 +347,7 @@ static enum hrtimer_restart watchdog_timer_fn(struct hrtimer *hrtimer)
 	 * this is a good indication some task is hogging the cpu
 	 */
 	duration = is_softlockup(touch_ts);
+	printk("%d: watchdog process kicked (%d seconds since last)\n", smp_processor_id(), duration);
 	if (unlikely(duration)) {
 		/*
 		 * If a virtual machine is stopped by the host it can look to

@@ -477,6 +479,7 @@ static void watchdog(unsigned int cpu)
 	__this_cpu_write(soft_lockup_hrtimer_cnt,
 			 __this_cpu_read(hrtimer_interrupts));
 	__touch_watchdog();
+	printk("%d: watchdog run\n", cpu);
 }
 
 #ifdef CONFIG_HARDLOCKUP_DETECTOR

I COULD trigger it with 3.17. Took much longer, but I've seen it once. And from Xen hypervisor data it was clear it was the same bug (cpu spinning in pmd_lock()).

Juergen

Before giving 3.17 a multi-day workout, I'll try rc6 with Jürgen's patch to see if that makes any difference at all for me.

Dave

Working on it. Triggering it via sysrq(l) isn't working: machine hung up. I'll try a dump, but this might take some time due to the machine size...

If this isn't working I can always modify the hypervisor to show me more of the kernel stack in that situation. This will be a pure dump, but it should be possible to extract the back trace from that.

Sure.

Stay tuned... :-)

Juergen

Actually, in that patch that did this:

- pgd = pgd_offset(current->active_mm, address);
+ pgd = (pgd_t *)__va(read_cr3()) + pgd_index(address);

make the code do:

        pgd = (pgd_t *)__va(read_cr3()) + pgd_index(address);
        WARN_ON(pdg != pgd_offset(current->active_mm, address));

and now you should get a nice backtrace for exactly when it happens, but it's on a working kernel, so nothing will lock up.

Hmm?

And leave it running for a while, and see if the trace is always the same, or if there are variations on it...

Thanks,

Linus

Amusing.

Lookie here:

http://lists.xenproject.org/archives/html/xen-changelog/2005-08/msg00310.html

That's from 2005.

Anyway, I don't see why the cr3 issue matters, *unless* there is some situation where the scheduler can run with interrupts enabled. And why this is Xen-related, I have no idea.

The Xen patches seem to have lost that

/* On Xen the line below does not always work. Needs investigating! */

line when backporting the 2.6.29 patches to Xen. And clearly nobody investigated.

So please do get me back-traces, and we'll investigate. Better late than never. But it does sound Xen-specific - although it's possible that Xen just triggers some timing (and has apparently been able to trigger it since 2005) that DaveJ now triggers on his one machine.

So DaveJ, even though this does appear Xen-centric (Xentric?) and you're running on bare hardware, maybe you could do the same thing in that x86-64 vmalloc_fault(). The timing with Jürgen is kind of intriguing - if 3.18-rc made it happen much more often for him, maybe it really is very timing-sensitive, and you actually are seeing a non-Xen version of the same thing...

Linus

:-)

Yeah, this sounds plausible.

I'm working on the back traces right now, hope to have them soon.

Juergen

Very interesting: I've updated my test-machine yesterday to the newest Xen version after I've got rid of the lockups to avoid another problem I was seeing. With this version I don't get the lockups any more even with the unmodified 3.18-rc kernel.

Digging deeper I found something making me believe I've seen another issue than Dave which just looked similar on the surface. :-(

My Xen problem was related to an error in freeing grant pages (pages mapped in from another domain). One detail in the handling of such mappings is interesting: the "private" member of the page structure is used to hold the machine frame number of the mapped memory page. Another usage of this "private" member is in the pgd handling of Xen (see xen_pgd_alloc() and xen_get_user_pgd()) to hold the pgd of the user address space (kernel and user are in separate address spaces on Xen). So with an error in the grant page handling I could imagine a pgd's private member could be clobbered leading to effects like the one I've observed. And this could have been the problem in 2005, too.

And why is my patch working? I think it's just because cr3 is always written with a page aligned value while the clobbered "private" member of the Xen pgd is not page aligned resulting in a different pointer. I'm still using the wrong page for the user's pgd, but this seems not to lead to fatal errors when nearly nothing is running on the machine. I've seen Xen messages occasionally indicating there was something wrong with the page table handling of the kernel (pages used as page tables not known to Xen as such).

I hope this all makes sense.

And just for the records: with the actual Xen version (tweaked to show the grant page error again) I see different lockups with the following backtrace:

[ 1122.256305] NMI watchdog: BUG: soft lockup - CPU#94 stuck for 23s! [systemd-udevd:1179]
[ 1122.303427] Modules linked in: xen_blkfront msr bridge stp llc iscsi_ibft ipmi_devintf nls_utf8 x86_pkg_temp_thermal intel_powerclamp nls_cp437 coretemp crct10dif_pclmul vfat crc32_pclmul fat crc32c_intel ghash_clmulni_intel snd_pcm aesni_intel aes_x86_64 snd_timer lrw be2iscsi be2net gf128mul libiscsi snd glue_helper joydev vxlan soundcore scsi_transport_iscsi ablk_helper iTCO_wdt ixgbe igb mdio ip6_udp_tunnel iTCO_vendor_support efivars evdev iscsi_boot_sysfs udp_tunnel cryptd dca pcspkr sb_edac e1000e edac_core lpc_ich i2c_i801 ptp mfd_core pps_core shpchp tpm_infineon ipmi_si tpm_tis ipmi_msghandler tpm button xenfs xen_privcmd xen_acpi_processor processor thermal_sys xen_pciback xen_netback xen_blkback xen_gntalloc xen_gntdev xen_evtchn dm_mod efivarfs crc32c_generic btrfs xor raid6_pq hid_generic
[ 1122.303450]  usbhid hid sd_mod mgag200 ehci_pci i2c_algo_bit ehci_hcd drm_kms_helper ttm usbcore drm megaraid_sas usb_common sg scsi_mod autofs4
[ 1122.303456] CPU: 94 PID: 1179 Comm: systemd-udevd Tainted: G 
    L 3.18.0-rc5+ #304
[ 1122.303458] Hardware name: FUJITSU PRIMEQUEST 2800E/SB, BIOS PRIMEQUEST 2000 Series BIOS Version 01.59 07/24/2014
[ 1122.303459] task: ffff881f17b56ce0 ti: ffff881f0fff0000 task.ti: ffff881f0fff0000
[ 1122.303460] RIP: e030:[<ffffffff814fcf5e>]  [<ffffffff814fcf5e>] _raw_spin_lock+0x1e/0x30
[ 1122.303462] RSP: e02b:ffff881f0fff3ce8  EFLAGS: 00000282
[ 1122.303463] RAX: 000000000000ba43 RBX: 00003ffffffff000 RCX: 0000000000000190
[ 1122.303464] RDX: 0000000000000190 RSI: 000000190ba43067 RDI: ffffea000157c350
[ 1122.303465] RBP: ffff880000000c70 R08: 0000000000000000 R09: 0000000000000000
[ 1122.303466] R10: 000000000001b688 R11: ffff881fdf24ad80 R12: ffffea0000000000
[ 1122.303466] R13: ffff88006237cc70 R14: 0000000000000000 R15: 00007f70f438e000
[ 1122.303470] FS:  00007f70f5c49880(0000) GS:ffff881f4c5c0000(0000) knlGS:ffff881f4c5c0000
[ 1122.303471] CS:  e033 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 1122.303472] CR2: 00007f70f5c68000 CR3: 0000001f111b7000 CR4: 0000000000042660
[ 1122.303473] Stack:
[ 1122.303474]  ffffffff81155850 ffff881fdf24ad80 00007f70f438f000 ffff881f138ae5d8
[ 1122.303476]  ffff881f08ead400 ffff881f0fff3fd8 0000000000000000 ffff881eff0cbd08
[ 1122.303477]  ffff881f18b57d08 ffffea000157c320 ffffea006ccc5ec8 ffff881f0fc00800
[ 1122.303479] Call Trace:
[ 1122.303481]  [<ffffffff81155850>] ? copy_page_range+0x460/0xa10
[ 1122.303484]  [<ffffffff8105d727>] ? copy_process.part.27+0x13e7/0x1b10
[ 1122.303486]  [<ffffffff81435f41>] ? netlink_insert+0x91/0xb0
[ 1122.303488]  [<ffffffff813f85c9>] ? release_sock+0x19/0x160
[ 1122.303490]  [<ffffffff8105dff8>] ? do_fork+0xc8/0x320
[ 1122.303492]  [<ffffffff814fd779>] ? stub_clone+0x69/0x90
[ 1122.303493]  [<ffffffff814fd42d>] ? system_call_fastpath+0x16/0x1b
[ 1122.303494] Code: 90 0f b7 17 66 39 d0 75 f6 eb e8 66 90 b8 00 00 01 00 f0 0f c1 07 89 c2 c1 ea 10 66 39 c2 89 d1 75 01 c3 0f b7 07 66 39 d0 74 f7 <f3> 90 0f b7 07 66 39 c8 75 f6 c3 0f 1f 80 00 00 00 00 65 81 04

But if my assumptions above are correct this is meaningless, as using an arbitrary memory page as pgd might result in anything...

Juergen

I did try your WARN variant (after fixing the typo)

Woke up to the below trace. Looks like a different issue.

Nnngh.

Dave

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

CPU: 2 PID: 24766 Comm: trinity-c149 Not tainted 3.18.0-rc6+ #98 [loadavg: 156.09 150.24 148.56 21/402 26750]
task: ffff8802285b96f0 ti: ffff8802260e0000 task.ti: ffff8802260e0000
RIP: 0010:[<ffffffff8104658c>]  [<ffffffff8104658c>] kernel_map_pages+0xbc/0x120
RSP: 0018:ffff8802260e3768  EFLAGS: 00000202
RAX: 00000000001407e0 RBX: ffffffff817e0c24 RCX: 0000000000140760
RDX: 0000000000000202 RSI: ffff8800000006b0 RDI: 0000000000000001
RBP: ffff8802260e37c8 R08: 8000000000000063 R09: ffff880000000000
R10: 0000000000000001 R11: 0000000000000000 R12: ffff880200000001
R13: 0000000000010000 R14: 0000000001b60000 R15: 0000000000000000
FS:  00007fb8ef71d740(0000) GS:ffff880244400000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00000000018b87f0 CR3: 00000002277fe000 CR4: 00000000001407e0
DR0: 0000000000000000 DR1: 00007f60b71b4000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000600
Stack:
 ffff880123cd7000 ffff8802260e3768 0000000000000000 0000000000000003
 0000000000000000 0000000100000001 0000000000123cd6 0000000000000000
 0000000000000000 00000000ade00558 ffff8802445d7638 0000000000000001
Call Trace:
 [<ffffffff81185ebf>] get_page_from_freelist+0x49f/0xaa0
 [<ffffffff810a7431>] ? get_parent_ip+0x11/0x50
 [<ffffffff811866ee>] __alloc_pages_nodemask+0x22e/0xb60
 [<ffffffff810ad5c5>] ? local_clock+0x25/0x30
 [<ffffffff810c6e7c>] ? __lock_acquire.isra.31+0x22c/0x9f0
 [<ffffffff813775e0>] ? __radix_tree_preload+0x60/0xf0
 [<ffffffff810a7431>] ? get_parent_ip+0x11/0x50
 [<ffffffff810c546d>] ? lock_release_holdtime.part.24+0x9d/0x160
 [<ffffffff811d093e>] alloc_pages_vma+0xee/0x1b0
 [<ffffffff81194f0e>] ? shmem_alloc_page+0x6e/0xc0
 [<ffffffff810c6e7c>] ? __lock_acquire.isra.31+0x22c/0x9f0
 [<ffffffff81194f0e>] shmem_alloc_page+0x6e/0xc0
 [<ffffffff810a7431>] ? get_parent_ip+0x11/0x50
 [<ffffffff810a75ab>] ? preempt_count_sub+0x7b/0x100
 [<ffffffff8139ac66>] ? __percpu_counter_add+0x86/0xb0
 [<ffffffff811b2396>] ? __vm_enough_memory+0x66/0x1c0
 [<ffffffff8117cac5>] ? find_get_entry+0x5/0x120
 [<ffffffff81300937>] ? cap_vm_enough_memory+0x47/0x50
 [<ffffffff81197880>] shmem_getpage_gfp+0x4d0/0x7e0
 [<ffffffff81197bd2>] shmem_write_begin+0x42/0x70
 [<ffffffff8117c2d4>] generic_perform_write+0xd4/0x1f0
 [<ffffffff8117eac2>] __generic_file_write_iter+0x162/0x350
 [<ffffffff811f0070>] ? new_sync_read+0xd0/0xd0
 [<ffffffff8117ecef>] generic_file_write_iter+0x3f/0xb0
 [<ffffffff8117ecb0>] ? __generic_file_write_iter+0x350/0x350
 [<ffffffff811f01b8>] do_iter_readv_writev+0x78/0xc0
 [<ffffffff811f19e8>] do_readv_writev+0xd8/0x2a0
 [<ffffffff8117ecb0>] ? __generic_file_write_iter+0x350/0x350
 [<ffffffff8117ecb0>] ? __generic_file_write_iter+0x350/0x350
 [<ffffffff810c54b6>] ? lock_release_holdtime.part.24+0xe6/0x160
 [<ffffffff810a7431>] ? get_parent_ip+0x11/0x50
 [<ffffffff810a75ab>] ? preempt_count_sub+0x7b/0x100
 [<ffffffff817df36b>] ? _raw_spin_unlock_irq+0x3b/0x60
 [<ffffffff811f1c3c>] vfs_writev+0x3c/0x50
 [<ffffffff811f1dac>] SyS_writev+0x5c/0x100
 [<ffffffff817e0249>] tracesys_phase2+0xd4/0xd9
Code: 65 48 33 04 25 28 00 00 00 75 75 48 83 c4 50 5b 41 5c 5d c3 0f 1f 00 9c 5a fa 0f 20 e0 48 89 c1 80 e1 7f 0f 22 e1 0f 22 e0 52 9d <eb> cf 66 90 49 bc 00 00 00 00 00 88 ff ff 48 63 f6 49 01 fc 48 

sending NMI to other CPUs:

<nothing further on console, accidentally had panic=1 set>

Yeah, apparently the Xen issue was really just a Xen bug.

Well, this one at least makes some amount of sense. The "Code:" line says it's

  1b: 9c                   pushfq
  1c: 5a                   pop    %rdx
  1d: fa                   cli
  1e: 0f 20 e0             mov    %cr4,%rax
  21: 48 89 c1             mov    %rax,%rcx
  24: 80 e1 7f             and    $0x7f,%cl
  27: 0f 22 e1             mov    %rcx,%cr4
  2a: 0f 22 e0             mov    %rax,%cr4
  2d: 52                   push   %rdx
  2e: 9d                   popfq

2f:* eb cf jmp back <-- trapping instruction

and %rdx is 0x0202 which is actually a valid flags value.

That looks like the code for __native_flush_tlb_global().

Not that interrupt should have been disabled very long.

Hmm. Maybe some oom issue, that we spent a long time before this trying to free pages?

Linus

It looks like we are looping somewhere around syscall_trace_leave(). Maybe the TIF WORK_SYSCALL_EXIT flags aren't cleared properly after some of them got processed. Or something keeps setting a TIF_WORK_SYSCALL_EXIT flag after they get cleared and we loop endlessly to jump to int_check_syscall_exit_work().

Andi did some work there lately. Cc'ing him.

Hi Dave,

When I usually see stuff like this, it is because another cpu is blocking the IPI from smp_call_function_many from finishing, so this cpu waits forever.

The problem usually becomes obvious with a dump of all cpus at the time the lockup is detected.

Can you try adding 'softlockup_all_cpu_backtrace=1' to the kernel commandline? That should dump all the cpus to see if anything stands out.

Though I don't normally see it traverse down to smp_call_function_single.

Anyway something to try.

Cheers,
Don