printk vs rq->lock and xtime lock

kernel/time/timekeeping.c +5 -1

-       printk(KERN_INFO "Time: %s clocksource has been installed.\n",
+       /*
+        * We're holding xtime lock and waking up klogd would deadlock
+        * us on enqueue. Print without waking.
+        */
+       printk_nowakeup(KERN_INFO "Time: %s clocksource has been

installed.\n",

               clock->name);

Hi Linus,

As to the regression reported by Marcin; what happens is that we invoke printk() while holding the xtime lock for writing. printk() will call wake_up_klogd() which tries to enqueue klogd on some rq.

The known deadlock here is calling printk() while holding rq->lock, which would then try to recusively lock the rq again when trying to wake klogd.

The new deadlock is due to task enqueues setting an hrtimer, which requires reading the time, which will result in a live-lock when the printk() call- site is holding the xtime lock for writing.

Thomas would like to preserve the printk() information if possible, hence my proposal of printk_nowakeup(). It will do everything printk() normally does, except ommit to wake up of klogd. The call is explicitly not EXPORTed so that its use is confined to core kernel code.

Marcin, could you please test these two patches to confirm they do indeed solve your issue as well?

As to the regression reported by Marcin; what happens is that we invoke printk() while holding the xtime lock for writing. printk() will call wake_up_klogd() which tries to enqueue klogd on some rq.

The known deadlock here is calling printk() while holding rq->lock, which would then try to recusively lock the rq again when trying to wake klogd.

Quoted 7 lines · Peter Zijlstra

As to the regression reported by Marcin; what happens is that we invoke printk() while holding the xtime lock for writing. printk() will call wake_up_klogd() which tries to enqueue klogd on some rq.

The known deadlock here is calling printk() while holding rq->lock, which would then try to recusively lock the rq again when trying to wake klogd.

Ok.

Right now, however, I think that for 2.6.25 I'll just remove the printk.

And for the long haul, I really don't think the solution is "printk_nowakup()", because this is going to happen again when somebody doesn't realize the code is called with the rq lock held, and it's going to be a bitch to debug.

I just don't think this is maintainable.

How about I use the lockdep infrastructure to check if printk() is invoked whole holding either xtime or rq lock, and then avoid calling wake_up_klogd(). That way, we at least get sane debug output when the lock debugging infrastructure is enabled?

Quoted 4 lines · On Mon, 24 Mar 2008 19:15:47 +0100 Peter Zijlstra <[email protected]>…

How about I use the lockdep infrastructure to check if printk() is invoked whole holding either xtime or rq lock, and then avoid calling wake_up_klogd(). That way, we at least get sane debug output when the lock debugging infrastructure is enabled?

The core problem seems to be that printk shouldn't be calling wake_up(). Can we fix that?

I expect it would be acceptable to do it from the timer interrupt instead. For NOHZ kernels a poll when we enter the idle loop would also be needed.

But does that cover everything? Is it possible for a CPU to run 100% busy while not receiving timer interrupts? I guess so. To receive no interrupts at all? Also possible.

Quoted 8 lines · Andrew Morton

Quoted 4 lines · On Mon, 24 Mar 2008 19:15:47 +0100 Peter Zijlstra <[email protected]>…

How about I use the lockdep infrastructure to check if printk() is invoked whole holding either xtime or rq lock, and then avoid calling wake_up_klogd(). That way, we at least get sane debug output when the lock debugging infrastructure is enabled?

Quoted 5 lines

The core problem seems to be that printk shouldn't be calling wake_up(). Can we fix that?

I expect it would be acceptable to do it from the timer interrupt instead. For NOHZ kernels a poll when we enter the idle loop would also be needed.

Something along the lines of the below patch?

Quoted 3 lines

But does that cover everything? Is it possible for a CPU to run 100% busy while not receiving timer interrupts? I guess so. To receive no interrupts at all? Also possible.

local_irq_disable(); while (1);

But I guess you have more pressing issues when that happens..

---

Something along the lines of the below patch?

Quoted 2 lines · Peter Zijlstra

Something along the lines of the below patch?

Could we not literally just make this a RCU event? Unconditionally too?

Sure, but the RCU callback period is at least 3 jiffies and much longer when busy - I'm not sure how long before we force a grace period, we do that to avoid DoS, right Paul?

So this version would have a much higher risk of overflowing the console buffer and making klogd miss bits. Then again, I really don't care about klogd at _all_, I've been running with the wakeup patched out for ages.

Gah, the below doesn't boot - because I guess we start using rcu before its properly set up.. should I poke at it more?

Quoted 4 lines · Peter Zijlstra

Sure, but the RCU callback period is at least 3 jiffies and much longer when busy - I'm not sure how long before we force a grace period, we do that to avoid DoS, right Paul?

I really don't think it matters. klogd is going to write the thing to _disk_ (or network), and three jiffies really don't matter. If we can fill the buffer in that kind of time, we're screwed for other reasons anyway.

Quoted 3 lines

So this version would have a much higher risk of overflowing the console buffer and making klogd miss bits. Then again, I really don't care about klogd at _all_, I've been running with the wakeup patched out for ages.

Well, I'd care a _bit_ about klogd, but not enough to worry about a couple of jiffies. We want to wake it up at some point, but...

Quoted 2 lines

Gah, the below doesn't boot - because I guess we start using rcu before its properly set up.. should I poke at it more?

I'd certainly prefer this kind of approach. However, may I suggest:

- doing the "waitqueue_active(&log_wait)" before even bothering to do the RCU call. That, btw, will automatically mean that we wouldn't ever call the RCU code before anything is initialized.

- get rid of the "oops_in_progress" thing, since I think the whole point of that was to avoid getting the lock recursively in the first place.

- I'd worry about the "spin_lock_irqsave(&klogd_wakeup_state.lock)". What if the printk happens from call_rcu()? This is exactly what we're trying to get away from - having some parts of the kernel not able to printk() because of subtle locking issues.

For that last thing, maybe we can just make it a percpu thing and just disable irq's?

Avoid deadlocks against rq->lock and xtime_lock by using RCU to defer the klogd wakeup.

Quoted 3 lines · Peter Zijlstra

Avoid deadlocks against rq->lock and xtime_lock by using RCU to defer the klogd wakeup.

Ok, I can't see anything wrong with this from the patch. I do hate that deadlock, so I think I'll apply it. But I'll try to hold off for a while in case somebody has any last-minute comments..

void wake_up_klogd(void)
{

kernel/printk.c +4 -2

-	if (!oops_in_progress && waitqueue_active(&log_wait))
-		wake_up_interruptible(&log_wait);
+	unsigned long flags;
+	struct klogd_wakeup_state *kws;
+
+	if (!waitqueue_active(&log_wait))

From a quick look it appears that large amounts of kernel/rcupreempt.c

Quoted 8 lines · On Fri, 08 Aug 2008 20:14:28 +0200 Peter Zijlstra <[email protected]>…

void wake_up_klogd(void)
{

kernel/printk.c +4 -2

-	if (!oops_in_progress && waitqueue_active(&log_wait))
-		wake_up_interruptible(&log_wait);
+	unsigned long flags;
+	struct klogd_wakeup_state *kws;
+
+	if (!waitqueue_active(&log_wait))

kernel/printk.c int is_console_locked(void) · line 1017

Quoted 10 lines

kernel/printk.c +9 -0

+		return;
+
+	local_irq_save(flags);
+	kws = &__get_cpu_var(kws);
+	if (!kws->pending) {
+		kws->pending = 1;
+		call_rcu(&kws->head, __wake_up_klogd);
+	}
+	local_irq_restore(flags);
 }

Note that kernel/rcupreempt.c's flavour of call_rcu() takes RCU_DATA_ME().lock, so there are still code sites from which a printk can deadlock. Only now, it is config-dependent.

From a quick look it appears that large amounts of kernel/rcupreempt.c are now a printk-free zone.

Quoted 26 lines · Andrew Morton

Quoted 8 lines · On Fri, 08 Aug 2008 20:14:28 +0200 Peter Zijlstra <[email protected]>…

void wake_up_klogd(void)
{

kernel/printk.c +4 -2

-	if (!oops_in_progress && waitqueue_active(&log_wait))
-		wake_up_interruptible(&log_wait);
+	unsigned long flags;
+	struct klogd_wakeup_state *kws;
+
+	if (!waitqueue_active(&log_wait))

kernel/printk.c int is_console_locked(void) · line 1017

Quoted 10 lines

kernel/printk.c +9 -0

+		return;
+
+	local_irq_save(flags);
+	kws = &__get_cpu_var(kws);
+	if (!kws->pending) {
+		kws->pending = 1;
+		call_rcu(&kws->head, __wake_up_klogd);
+	}
+	local_irq_restore(flags);
 }

Note that kernel/rcupreempt.c's flavour of call_rcu() takes RCU_DATA_ME().lock, so there are still code sites from which a printk can deadlock. Only now, it is config-dependent.

Quoted 2 lines

From a quick look it appears that large amounts of kernel/rcupreempt.c are now a printk-free zone.

Drad, missed that bit, I did look at the calling end, but forgot the call_rcu() end :-/

The initial printk_tick() based implementation didn't suffer this problem, should we revert to that scheme?

Quoted 27 lines · On Fri, 08 Aug 2008 21:21:08 +0200 Peter Zijlstra <[email protected]>…

Quoted 26 lines · Andrew Morton

Quoted 8 lines · On Fri, 08 Aug 2008 20:14:28 +0200 Peter Zijlstra <[email protected]>…

void wake_up_klogd(void)
{

kernel/printk.c +4 -2

-	if (!oops_in_progress && waitqueue_active(&log_wait))
-		wake_up_interruptible(&log_wait);
+	unsigned long flags;
+	struct klogd_wakeup_state *kws;
+
+	if (!waitqueue_active(&log_wait))

kernel/printk.c int is_console_locked(void) · line 1017

Quoted 10 lines

kernel/printk.c +9 -0

+		return;
+
+	local_irq_save(flags);
+	kws = &__get_cpu_var(kws);
+	if (!kws->pending) {
+		kws->pending = 1;
+		call_rcu(&kws->head, __wake_up_klogd);
+	}
+	local_irq_restore(flags);
 }

Note that kernel/rcupreempt.c's flavour of call_rcu() takes RCU_DATA_ME().lock, so there are still code sites from which a printk can deadlock. Only now, it is config-dependent.

Quoted 8 lines

Quoted 2 lines

From a quick look it appears that large amounts of kernel/rcupreempt.c are now a printk-free zone.

Drad, missed that bit, I did look at the calling end, but forgot the call_rcu() end :-/

The initial printk_tick() based implementation didn't suffer this problem, should we revert to that scheme?

Dunno. Perhaps we could convert RCU_DATA_ME's spinlock_t into an rwlock and do read_lock() in call_rcu()? Then we can should be able to call printk from inside that read_lock(), but not inside write_lock(), which, with suitable warning comments might be acceptable.

afacit everything in call_rcu()'s *rdp is cpu-local and is protected by local_irq_save(). rcu_ctrlblk.completed and rcu_flipped need some protection, but a) rdp->lock isn't sufficient anyway and b) read_lock protection would suffice. Maybe other CPUs can alter *rdp while __rcu_advance_callbacks() is running.

Anyway, that's all handwaving. My point is that making rcupreempt.c more robust and more concurrent might be an alternative fix, and might be beneficial in its own right. Working out the details is what we have Pauls for ;)

Quoted 27 lines · On Fri, 08 Aug 2008 21:21:08 +0200 Peter Zijlstra <[email protected]>…

Quoted 26 lines · Andrew Morton

Quoted 8 lines · On Fri, 08 Aug 2008 20:14:28 +0200 Peter Zijlstra <[email protected]>…

void wake_up_klogd(void)
{

kernel/printk.c +4 -2

-	if (!oops_in_progress && waitqueue_active(&log_wait))
-		wake_up_interruptible(&log_wait);
+	unsigned long flags;
+	struct klogd_wakeup_state *kws;
+
+	if (!waitqueue_active(&log_wait))

kernel/printk.c int is_console_locked(void) · line 1017

Quoted 10 lines

kernel/printk.c +9 -0

+		return;
+
+	local_irq_save(flags);
+	kws = &__get_cpu_var(kws);
+	if (!kws->pending) {
+		kws->pending = 1;
+		call_rcu(&kws->head, __wake_up_klogd);
+	}
+	local_irq_restore(flags);
 }

Note that kernel/rcupreempt.c's flavour of call_rcu() takes RCU_DATA_ME().lock, so there are still code sites from which a printk can deadlock. Only now, it is config-dependent.

Quoted 8 lines

Quoted 2 lines

From a quick look it appears that large amounts of kernel/rcupreempt.c are now a printk-free zone.

Drad, missed that bit, I did look at the calling end, but forgot the call_rcu() end :-/

The initial printk_tick() based implementation didn't suffer this problem, should we revert to that scheme?

Dunno. Perhaps we could convert RCU_DATA_ME's spinlock_t into an rwlock and do read_lock() in call_rcu()? Then we can should be able to call printk from inside that read_lock(), but not inside write_lock(), which, with suitable warning comments might be acceptable.

afacit everything in call_rcu()'s *rdp is cpu-local and is protected by local_irq_save(). rcu_ctrlblk.completed and rcu_flipped need some protection, but a) rdp->lock isn't sufficient anyway and b) read_lock protection would suffice. Maybe other CPUs can alter *rdp while __rcu_advance_callbacks() is running.

Anyway, that's all handwaving. My point is that making rcupreempt.c more robust and more concurrent might be an alternative fix, and might be beneficial in its own right. Working out the details is what we have Pauls for ;)

How about if I instead add comments warning people not to put printk() in the relevant RCU-implementation code? That way I can be not only lazy, but cowardly as well! ;-)

Quoted 3 lines · Paul E. McKenney

How about if I instead add comments warning people not to put printk() in the relevant RCU-implementation code? That way I can be not only lazy, but cowardly as well! ;-)

Well, it does spoil the party a little, we are now trading one deadlock for another :-/

Quoted 3 lines · Paul E. McKenney

How about if I instead add comments warning people not to put printk() in the relevant RCU-implementation code? That way I can be not only lazy, but cowardly as well! ;-)

Well, it does spoil the party a little, we are now trading one deadlock for another :-/

Why are we fixing this, btw? The problem has been there forever and people who hack the wakeup code could/should know about it anyway. All they need to do is to disable klogd during development. Did the problem recently become worse for some reason?

Quoted 5 lines · Andrew Morton

Why are we fixing this, btw? The problem has been there forever and people who hack the wakeup code could/should know about it anyway. All they need to do is to disable klogd during development. Did the problem recently become worse for some reason?

It hasn't beemn there forever at all.

Yes, there used to be reliance on the actual _scheduler_ locks. Doign a wake_up() would cause runqueue locks etc to be taken.

But the xtime deadlock is fairly recent, and only happened with CFQ, I think.

And _that_ is the irritating one. I personally wouldn't mind at all if there is some printk() dependency on the core runqueue rq->lock or on the RCU locking thing. But look at xtime_lock. THAT is a disaster.

Just grep for it.

So I personally actually like the RCU version best. Yes, it still depends on really core locking. But it's really core and low-level and _confined_ locking, where a comment in a single place would probably suffice. Compare that to all the places where we take the xtime_lock for writing!

The initial printk_tick() based implementation didn't suffer this problem, should we revert to that scheme?

Quoted 2 lines · Peter Zijlstra

The initial printk_tick() based implementation didn't suffer this problem, should we revert to that scheme?

Just in case people care..

---
Subject: printk: robustify printk

Avoid deadlocks against rq->lock and xtime_lock by deferring the klogd wakeup by polling from the timer tick.

Quoted 7 lines · Peter Zijlstra

Quoted 2 lines · Peter Zijlstra

The initial printk_tick() based implementation didn't suffer this problem, should we revert to that scheme?

Just in case people care..

Quoted 5 lines

---
Subject: printk: robustify printk

Avoid deadlocks against rq->lock and xtime_lock by deferring the klogd wakeup by polling from the timer tick.

i missed most of the discussion, but this seems like the simplest (and hence ultimately the best) approach to me.

Coupling printk with RCU, albeit elegant, does not seem like the right choice to me in this specific case: printk as an essential debug mechanism should be as decoupled as possible.

Quoted 9 lines · Ingo Molnar

Quoted 7 lines · Peter Zijlstra

Quoted 2 lines · Peter Zijlstra

The initial printk_tick() based implementation didn't suffer this problem, should we revert to that scheme?

Just in case people care..

Quoted 8 lines

Quoted 5 lines

---
Subject: printk: robustify printk

Avoid deadlocks against rq->lock and xtime_lock by deferring the klogd wakeup by polling from the timer tick.

i missed most of the discussion, but this seems like the simplest (and hence ultimately the best) approach to me.

The problem is that it means any printk data output that is more than DMESG-BUFFER-SIZE bytes during one clock tick is going to lose data. It loses the natural adaption to higher printk rates that you got previously.

Now we could say that for debugging etc. people should switch to other mechanisms like relayfs, but I would still worry about some corner cases where losing printk data that wasn't lost before could be a severe regression (e.g. consider firewall log messages or similar)

Essentially it makes printk (much?) less reliable than it was before in the general case. Not sure that's a good thing. So the patch title is definitely misleading.

As Linus pointed out earlier we've survived with this restriction (not doing printk in the scheduler) for a long time, so is there really a that pressing need to change that?

You only loose the msgs with klogd, console still gets everything. If firewalls are generating that much data, perhaps its time to think about alternative ways to channel that.

Quoted 4 lines

Essentially it makes printk (much?) less reliable than it was before in the general case. Not sure that's a good thing. So the patch title is definitely misleading.

Depends, I don't give a rats arse about klogd - I get everything through serial onto another machine.

Quoted 3 lines

As Linus pointed out earlier we've survived with this restriction (not doing printk in the scheduler) for a long time, so is there really a that pressing need to change that?

Why not fix it if its acceptable - the deadlock is just ugly.

Quoted 3 lines · Peter Zijlstra

You only loose the msgs with klogd, console still gets everything. If firewalls are generating that much data, perhaps its time to think about alternative ways to channel that.

Yes, and netfilter has them in fact, but it's clearly still a regression for people who rely on klogd for this today.

Also firewall is just an example. Other cases might be people relying on these selinux messages. Or some other kernel messages.

$INSERT-ANY-OTHER-PRINTK-USE$

The point was that printk may have been perfectly adequate for them with its existing buffer sizes and dynamic wake up frequency, and might not anymore with the timer wakeup change. Essentially it is making a widely used kernel facility more fragile.

Quoted 10 lines

The problem is that it means any printk data output that is more than DMESG-BUFFER-SIZE bytes during one clock tick is going to lose data. It loses the natural adaption to higher printk rates that you got previously.

Now we could say that for debugging etc. people should switch to other mechanisms like relayfs, but I would still worry about some corner cases where losing printk data that wasn't lost before could be a severe regression (e.g. consider firewall log messages or similar)

You only loose the msgs with klogd, console still gets everything. If firewalls are generating that much data, perhaps its time to think about alternative ways to channel that.

That's a rather misleading argument, because klogd as it stands today is already lossy: you can overflow it with enough printk data. (It's rather

Quoted 5 lines · Peter Zijlstra

Quoted 2 lines · Peter Zijlstra

The initial printk_tick() based implementation didn't suffer this problem, should we revert to that scheme?

Quoted 7 lines

Just in case people care..

---
Subject: printk: robustify printk

Avoid deadlocks against rq->lock and xtime_lock by deferring the klogd wakeup by polling from the timer tick.

i missed most of the discussion, but this seems like the simplest (and hence ultimately the best) approach to me.

Coupling printk with RCU, albeit elegant, does not seem like the right choice to me in this specific case: printk as an essential debug mechanism should be as decoupled as possible.

Also, once we accept the possibility of async klogd completion, we might as well do it all the time.

i have only one sidenote:

kernel/time/tick-sched.c void tick_nohz_stop_sched_tick(int inidl · line 259

Quoted 9 lines

kernel/time/tick-sched.c +1 -1

@@ -255,7 +255,7 @@ void tick_nohz_stop_sched_tick(int inidl
      next_jiffies = get_next_timer_interrupt(last_jiffies);
      delta_jiffies = next_jiffies - last_jiffies;
 
-     if (rcu_needs_cpu(cpu))
+     if (rcu_needs_cpu(cpu) || printk_needs_cpu(cpu))
              delta_jiffies = 1;

this change made a previous design quirks even more visible: these are items that are not purely event driven but need some polling component. RCU is one, and now printk is another.

We could clean this up further by integrating the rcu_needs_cpu() and printk_needs_cpu() into a softirq mechanism. We already check for pending softirqs in tick-sched.c, so the above complication would go away completely.

( But that's for a separate cleanup patch i think. )

No strong feelings though. Peter, which one do you prefer?

Quoted 4 lines

We could clean this up further by integrating the rcu_needs_cpu() and printk_needs_cpu() into a softirq mechanism. We already check for pending softirqs in tick-sched.c, so the above complication would go away completely.

RCU depends on the polling to advance the state machine, if you want an event driven state machine, you'd have to drive it from rcu_read_unlock() adding overhead there - and I'm pretty sure you don't want to do that.

So while its a tad ugly to poll for these states, I'm not too worried in these two cases - of course every additional poll needs good justification.

Quoted 3 lines

( But that's for a separate cleanup patch i think. )

No strong feelings though. Peter, which one do you prefer?

I personally prefer this printk_tick() driven one over the RCU driven one because it doesn't trade deadlocks.

From b845b517b5e3706a3729f6ea83b88ab85f0725b0 Mon Sep 17 00:00:00 2001

Quoted 2 lines

I personally prefer this printk_tick() driven one over the RCU driven one because it doesn't trade deadlocks.

i've started testing it in tip/core/printk to give it some track record - thanks Peter.

From 99fc8ce41d639ce46f32c4e8618e8a571858e5aa Mon Sep 17 00:00:00 2001

----------------->

Quoted 1 line

From b845b517b5e3706a3729f6ea83b88ab85f0725b0 Mon Sep 17 00:00:00 2001

From: Peter Zijlstra <[email protected]>
Date: Fri, 8 Aug 2008 21:47:09 +0200
Subject: [PATCH] printk: robustify printk

Avoid deadlocks against rq->lock and xtime_lock by deferring the klogd wakeup by polling from the timer tick.

Signed-off-by Peter Zijlstra <[email protected]>

Signed-off-by Ingo Molnar <[email protected]>

Quoted 6 lines · Ingo Molnar

----------------->

Quoted 1 line

From b845b517b5e3706a3729f6ea83b88ab85f0725b0 Mon Sep 17 00:00:00 2001

From: Peter Zijlstra <[email protected]>
Date: Fri, 8 Aug 2008 21:47:09 +0200
Subject: [PATCH] printk: robustify printk

Quoted 5 lines

Avoid deadlocks against rq->lock and xtime_lock by deferring the klogd wakeup by polling from the timer tick.

Signed-off-by Peter Zijlstra <[email protected]>

Signed-off-by Ingo Molnar <[email protected]>

Then I think we also want the patch below on top of that, right?

From: Jiri Kosina <[email protected]>
printk: robustify printk, fix #3

Remove the comment describing the possibility of printk() deadlocking on runqueue lock.

Signed-off-by Jiri Kosina <[email protected]>

---

 kernel/printk.c |    3 ---
 1 files changed, 0 insertions(+), 3 deletions(-)

kernel/printk.c +0 -3

index b51b156..9fbf391 100644
@@ -577,9 +577,6 @@ static int have_callable_console(void)
  * @fmt: format string
  *
  * This is printk().  It can be called from any context.  We want it to work.
- * Be aware of the fact that if oops_in_progress is not set, we might try to
- * wake klogd up which could deadlock on runqueue lock if printk() is called
- * from scheduler code.
  *
  * We try to grab the console_sem.  If we succeed, it's easy - we log the output and
  * call the console drivers.  If we fail to get the semaphore we place the output

Quoted 4 lines

Remove the comment describing the possibility of printk() deadlocking on runqueue lock.

Signed-off-by Jiri Kosina <[email protected]>

Acked-by Peter Zijlstra <[email protected]>

Quoted 3 lines · Ingo Molnar

( But that's for a separate cleanup patch i think. )

No strong feelings though. Peter, which one do you prefer?

I personally prefer this printk_tick() driven one over the RCU driven one because it doesn't trade deadlocks.

Quoted 5 lines · Peter Zijlstra

Quoted 2 lines · Peter Zijlstra

The initial printk_tick() based implementation didn't suffer this problem, should we revert to that scheme?

Quoted 7 lines

Just in case people care..

---
Subject: printk: robustify printk

Avoid deadlocks against rq->lock and xtime_lock by deferring the klogd wakeup by polling from the timer tick.

i missed most of the discussion, but this seems like the simplest (and hence ultimately the best) approach to me.

Coupling printk with RCU, albeit elegant, does not seem like the right choice to me in this specific case: printk as an essential debug mechanism should be as decoupled as possible.

Also, once we accept the possibility of async klogd completion, we might as well do it all the time.

i have only one sidenote:

kernel/time/tick-sched.c void tick_nohz_stop_sched_tick(int inidl · line 259

Quoted 9 lines

kernel/time/tick-sched.c +1 -1

@@ -255,7 +255,7 @@ void tick_nohz_stop_sched_tick(int inidl
      next_jiffies = get_next_timer_interrupt(last_jiffies);
      delta_jiffies = next_jiffies - last_jiffies;
 
-     if (rcu_needs_cpu(cpu))
+     if (rcu_needs_cpu(cpu) || printk_needs_cpu(cpu))
              delta_jiffies = 1;

this change made a previous design quirks even more visible: these are items that are not purely event driven but need some polling component. RCU is one, and now printk is another.

We could clean this up further by integrating the rcu_needs_cpu() and printk_needs_cpu() into a softirq mechanism. We already check for pending softirqs in tick-sched.c, so the above complication would go away completely.

( But that's for a separate cleanup patch i think. )

No strong feelings though. Peter, which one do you prefer?

Ingo

Quoted 14 lines · On Fri, 08 Aug 2008 20:14:28 +0200 Peter Zijlstra <[email protected]>…

void wake_up_klogd(void)
{

kernel/printk.c +10 -2

-	if (!oops_in_progress && waitqueue_active(&log_wait))
-		wake_up_interruptible(&log_wait);
+	unsigned long flags;
+	struct klogd_wakeup_state *kws;
+
+	if (!waitqueue_active(&log_wait))
+		return;
+
+	local_irq_save(flags);
+	kws = &__get_cpu_var(kws);
+	if (!kws->pending) {
+		kws->pending = 1;

kernel/printk.c int is_console_locked(void) · line 1017

Quoted 4 lines

kernel/printk.c +3 -0

+		call_rcu(&kws->head, __wake_up_klogd);
+	}
+	local_irq_restore(flags);
 }

Note that kernel/rcupreempt.c's flavour of call_rcu() takes RCU_DATA_ME().lock, so there are still code sites from which a printk can deadlock. Only now, it is config-dependent.

Quoted 1 line

From a quick look it appears that large amounts of kernel/rcupreempt.c

are now a printk-free zone.

Avoid deadlocks against rq->lock and xtime_lock by using RCU to defer the klogd wakeup.

Signed-off-by Peter Zijlstra <[email protected]>

Acked-by Steven Rostedt <[email protected]>

---

kernel/printk.c +30 -2

index b51b156..8870c2e 100644
@@ -32,6 +32,7 @@
 #include <linux/security.h>
 #include <linux/bootmem.h>
 #include <linux/syscalls.h>
+#include <linux/rcupdate.h>
 
 #include <asm/uaccess.h>
 

@@ -982,10 +983,37 @@ int is_console_locked(void)
 	return console_locked;
 }
 
+struct klogd_wakeup_state {
+	struct rcu_head head;
+	int pending;
+};
+
+DEFINE_PER_CPU(struct klogd_wakeup_state, kws);
+
+void __wake_up_klogd(struct rcu_head *head)
+{
+	struct klogd_wakeup_state *kws = 
+		container_of(head, struct klogd_wakeup_state, head);
+
+	wake_up_interruptible(&log_wait);
+	kws->pending = 0;
+}
+
 void wake_up_klogd(void)
 {
-	if (!oops_in_progress && waitqueue_active(&log_wait))
-		wake_up_interruptible(&log_wait);
+	unsigned long flags;
+	struct klogd_wakeup_state *kws;
+
+	if (!waitqueue_active(&log_wait))
+		return;
+
+	local_irq_save(flags);
+	kws = &__get_cpu_var(kws);
+	if (!kws->pending) {
+		kws->pending = 1;
+		call_rcu(&kws->head, __wake_up_klogd);
+	}
+	local_irq_restore(flags);
 }
 
 /**

From: Peter Zijlstra <[email protected]>
Date: Fri, 08 Aug 2008 20:14:28 +0200

kernel/printk.c int is_console_locked(void) · line 991

Quoted 6 lines

kernel/printk.c +6 -0

+struct klogd_wakeup_state {
+	struct rcu_head head;
+	int pending;
+};
+
+DEFINE_PER_CPU(struct klogd_wakeup_state, kws);

Since there is not RCU_HEAD_INIT() made on these per-cpu objects, this code is depending upon the fact that currently the RCU head is just initialized to all zeros.

Quoted 3 lines

For that last thing, maybe we can just make it a percpu thing and just disable irq's?

You're _so_ right! :-)

This is much prettier and boots to boot.

Signed-off-by Peter Zijlstra <[email protected]>

Right now, however, I think that for 2.6.25 I'll just remove the printk.