[ This patch is added to the series since the wakeup timings trace

  may lockup without it. ]
I thought that one could place a printk anywhere without worrying.

But it seems that it is not wise to place a printk where the runqueue

lock is held.
I just spent two hours debugging why some of my code was locking up,

to find that the lockup was caused by some debugging printk's that

I had in the scheduler.  The printk's were only in rare paths so

they shouldn't be too much of a problem, but after I hit the printk

the system locked up.
Thinking that it was locking up on my code I went looking down the

wrong path. I finally found (after examining an NMI dump) that

the lockup happened because printk was trying to wakeup the klogd

daemon, which caused a deadlock when the try_to_wakeup code tries

to grab the runqueue lock.
Since printks are seldom called with interrupts disabled, we can

hold off the waking of klogd if they are. We don't have access to

the runqueue locks from printk, but those locks need interrupts

disabled in order to be held. 
Calling printk with interrupts disabled should only be done for

emergencies and debugging anyway.
And with this patch, my code ran fine ;-)
Signed-off-by: Steven Rostedt <srostedt@redhat.com>

---

 kernel/printk.c |   16 ++++++++++++----

 1 file changed, 12 insertions(+), 4 deletions(-)
Index: linux-mcount.git/kernel/printk.c

===================================================================

--- linux-mcount.git.orig/kernel/printk.c	2008-01-18 06:29:15.000000000 -0500

+++ linux-mcount.git/kernel/printk.c	2008-01-18 06:32:38.000000000 -0500

@@ -595,9 +595,11 @@ 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.

+ *

+ * Note: if printk() is called with in...
[ message continues ]

This causes a regression .. When printk is called during an OOPS in

kernels without this change then the OOPS will get logged, since the

logging process (klogd) is woken to handle the messages.. If you apply

this change klogd doesn't wakeup, and hence doesn't log the oops.. So if

you remove the wakeup here you have to add it someplace else to maintain

the logging ..
(I'm not theorizing here, I have defects logged against this specific

piece of code..)
Daniel
--

Can we change this for :

if (!(irqs_disabled() && !oops_in_progress) && wake_klogd)

  wake_up_klogd();
?
--

Mathieu Desnoyers

Computer Engineering Ph.D. Student, Ecole Polytechnique de Montreal

OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

--

That's wrong, too.
Just make wake_up_klogd do trylock, if it finds that it can't get

neccessary locks, printk(KERN_ALERT) so at least console gets the

message, but proceed without the lock.

								Pavel

--

(english) http://www.livejournal.com/~pavelmachek

(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

--

!oops_in_progress is already inside wake_up_klogd().
Also, I think you'd want that first '!' inside the parens.
I've been working on a system to handle deferred displaying

of printk messages, when printk is called in interrupt context.

Currently on a serial console if printk is called with

ints disabled, it can hold interrupts off for up to 20

milliseconds.
My solution was to set up a worker thread to handle deferred

printk activity.  I don't think this works for the oops case,

because you don't want to defer the output.  However, I can

post this code if you think it would help with this problem.
I hesitate to just drop the call to wake_up_klogd() without

some kind of mechanism call it later.  Waiting until the

next printk will work to drain the buffer, but could lead

to indefinite intervals with printks waiting to be logged.

 -- Tim
=============================

Tim Bird

Architecture Group Chair, CE Linux Forum

Senior Staff Engineer, Sony Corporation of America

=============================
--

It wont get woken up anyway. Did you look at wake_up_klogd?
void wake_up_klogd(void)

{

	if (!oops_in_progress && waitqueue_active(&log_wait))

		wake_up_interruptible(&log_wait);

}
So if oops_in_progress is set, then it still wont get woken. Perhaps it

got woken some other way? Or is oops_in_progress not set in these oops?
One other solution is to make the runqueue locks visible externally. Like:
in sched.c:
int runqueue_is_locked(void)

{

	int cpu = get_cpu();

	struct rq *rq = cpu_rq(cpu);

	int ret;
	ret = spin_is_locked(&rq->lock);

	put_cpu();

	return ret;

}
And in printk we could do:
	if (wake_klogd && !runqueue_is_locked())

		wake_up_klogd();
This probably is the cleanest solution since it simply prevents the

deadlock from occurring.
-- Steve
--

Yes please... this looks like a solution to me.

									Pavel

--

(english) http://www.livejournal.com/~pavelmachek

(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

--

Do you really need to call it with the runqueue lock held .. There are

other issue with the calls at that level.. For instance in -rt these

call can actually hang the system in the console laying from inside

printk (something I reported more than 6 months ago) .. It would be

better to move them around the scheduler rather than inside it..
Daniel
--

The wakeup hook in schedule is when we find out that we hit our max. I

could postpone that somehow, but that would require more glue code than I

would like to add.
As for -rt, we've disabled printk for consoles not ATOMIC safe. So the

only consoles that will print in atomic sections so far are, earlyprintk

and the VGA.
Tim, could you send me your "postponed print" patches. That sounds like

something the -rt patch could use.
Thanks,
-- Steve
--

Sure.  See below.
This patch changes the way the printk code processes output to the

console buffer.  On some platforms, especially those with a serial

console, the way printk output the messages to console caused significant

interrupt-off periods.  This code introduces two config options to

improve that handling.
Without this change, test code run on a 178 MHZ ARM platform

showed an interrupt off period for a particularly long printk message

of 24 milliseconds.  With this patch applied, and the options set

to 'Y', the same message only had an interrupt-off period of

482 microseconds.
Portions of this (some parts that reorder locking and irq management

primitives) were taken from the RT-preempt patch.
The patch does several things:
   1. It moves the location of the irqrestore operations in the

   printk code, so that the console writing can occur with interrupts enabled
   2. It changes the code so that characters are written to the console

   one-at-a-time. The serial console code holds interrupts disabled for the

   duration of its output to the serial port. To decrease the interrupt-off

   time, only a small amount of data is written at a time. (This could be tuned

   by writing chunks larger than 1 character at a time, but the current solution

   was easiest, and gives the lowest interrupt-off times.)
   3. The printk code was changed so that if it is entered with interrupts

   disabled, it does not output to console immediately. Rather, a workqueue

   routine is scheduled to process the console output later (when interrupts

   are enabled).
   4. An init-time routine was created, to prevent trying to schedule the

   workqueue routine too early in the system boot sequence.
Here's the patch:
Signed-off-by: Tim Bird tim.bird@am.sony.com

---

 kernel/printk.c   |   92 	85 +	7 -	0 !

 lib/Kconfig.debug |   42 	42 +	0 -	0 !

 2 files changed, 127 insertions(+), 7 deletions(-)
Index: linux-2.6.24-rc8/kernel/printk.c

===========================================...
[ message continues ]

I suspect these features reduce the change a crash messages makes it out

onto the console, but fail to spot any of the copious text mention this
--

Anything not in interrupts would not be deferred.

The following code is meant to avoid deferring in oops as well.

I'm not sure if that covers all crash cases or not.
I made the code conditional because printk messages are pretty

critical for debugging, and I wanted someone to be aware if they

altered the behavior in any way.  I suspect that only in embedded,

when people are having realtime performance problems, would this

change be of interest.
Please recognize that I'm not submitting this for kernel inclusion

at this time.  Please see the larger thread for context.  That said,

I appreciate the feedback on the code.

 -- Tim
=============================

Tim Bird

Architecture Group Chair, CE Linux Forum

Senior Staff Engineer, Sony Corporation of America

=============================
--

Yes, using oops_in_progress seems an appropriate fix for that.
I assume that another downside is that printk-from-interrupt will now get

jumbled up with an interrupted pritk-from-non-interrupt.
Please use checkpatch.

--

No.  The order of printk messages (whether printk'ed

from interrupt context or not) should not be affected.

This patch should only affect the timing of when the

messages are output to console.
Note that an oops will flush any buffered messages

ahead of the oops messages themselves.
Some messages, not in oops, that were printk'ed in

interrupt context, may still be in the log buffer

but not have made it to console if the machine hangs

hard.  Because of this (IMO slight) downgrade in

debugging utility, I chose to make the changes
Will do from now on!  Thanks!

  -- Tim
=============================

Tim Bird

Architecture Group Chair, CE Linux Forum

Senior Staff Engineer, Sony Corporation of America

=============================
--

Is this code you added recently for tracing?
Daniel
--

The wakeup tracer does a print on max when the new task is about to be
Nope, it's been there for a few releases and had nothing to do with the

latency tracer.
<looks at code>
Hmm, seems that only the "hack" fix is in upstream. The Red Hat version

has the better fix, but mainline didn't get it. OK, I'll add that to the

next -rt release.
-- Steve
--

You can't move that hook to when the task actually starts running (i.e.
mainline ? The problem I'm thinking of was directly tracing related..
Daniel
--

I mean , why can't you?
Daniel
--

FYI :
kernel/panic.c
NORET_TYPE void panic(const char * fmt, ...)

{

....

bust_spinlocks(1);

...

bust_spinlocks(0);

...
In bust_spinlocks :
void __attribute__((weak)) bust_spinlocks(int yes)

{

        if (yes) {

                ++oops_in_progress;

        } else {

#ifdef CONFIG_VT

                unblank_screen();

#endif

                if (--oops_in_progress == 0)

                        wake_up_klogd();

        }

}
Where the final wake_up happens while oops_in_progress is 0, but

interrupts are still disabled.
So about my previous email, proposing testing oops_in_progress, it just

won't work.
--

Mathieu Desnoyers

Computer Engineering Ph.D. Student, Ecole Polytechnique de Montreal

OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

--