Re: [PATCH 1/3] printk: Release console_sem after logbuf_lock

On Fri, 2011-06-10 at 13:28 +0200, Peter Zijlstra wrote:

On Thu, 2011-06-09 at 16:57 -0700, Hugh Dickins wrote:

quoted

All console-related activity curently happens under spin_lock_irqsave(&console_lock). 
This causes interrutps to be blocked for 1-2 milliseconds with vgacon, and for
hundreds of milliseconds with fbdevs.  This results in network overruns, audio
dropouts, dropped characters on serial ports and other such nice things.

Hmm, with these proposed patches we're actually back to that. I wonder
if fbdev is still that crappy..

So I tried adding a fbcon to my test box (not that it actually has a
display, but who cares) and disabled lockdep (otherwise that's all I can
catch on the latency tracer) to see if I could see whopping horrid
latencies there, but I'm afraid I either failed to set things up
properly or my fbcon isn't sucky enough.

What I did was enable:

CONFIG_FB=y
CONFIG_FB_SIS=y
CONFIG_FB_SIS_315=y (the board has XGI z7)

and

CONFIG_FRAMEBUFFER_CONSOLE=y

And used:

 debug ignore_loglevel sysrq_always_enabled console=tty0
console=ttyS0,115200 earlyprintk=serial,ttyS0,115200

thinking that that would have my printk stmts appear on both the fbcon
as well as the serial line. But they fail to appear on the latency
tracer (current max was 165us waking an idle cpu).

Paul (and fellow fbcon folks), was my setup above correct, and what's
the current status of suckyness wrt fbcon output?

The idea is to keep IRQs disabled over all of printk() including the
con->write() calls, Andrew seems to be responsible removing that in the
early 2.4 time-frame due to some consoles being waaay crap and taking
like hundreds of ms to write things out, can that still happen or has
stuff improved and is using background flusher threads to write to slow
devices?

* Peter Zijlstra [off-list ref] wrote:

thinking that that would have my printk stmts appear on both the 
fbcon as well as the serial line. But they fail to appear on the 
latency tracer (current max was 165us waking an idle cpu).

Have you removed this bit:

                spin_unlock(&logbuf_lock);
                stop_critical_timings();        /* don't trace print latency */
                call_console_drivers(_con_start, _log_end);
                start_critical_timings();
                local_irq_restore(flags);

which hides the latencies from the latency tracer?

Thanks,

	Ingo

On Fri, 2011-06-10 at 14:34 +0200, Ingo Molnar wrote:

* Peter Zijlstra [off-list ref] wrote:

quoted

thinking that that would have my printk stmts appear on both the 
fbcon as well as the serial line. But they fail to appear on the 
latency tracer (current max was 165us waking an idle cpu).

Have you removed this bit:

                spin_unlock(&logbuf_lock);
                stop_critical_timings();        /* don't trace print latency */
                call_console_drivers(_con_start, _log_end);
                start_critical_timings();
                local_irq_restore(flags);

which hides the latencies from the latency tracer?

it shouldn't those flags come from spin_lock_irqsave(), which already
has IRQs disabled, so the restore shouldn't re-enable them.

Hmm,. that might actually already be true for mainline too, yeah, looks
like we call vprintk()->console_unlock() with IRQs-disabled.

Hohumm..

On Fri, 2011-06-10 at 14:41 +0200, Peter Zijlstra wrote:

On Fri, 2011-06-10 at 14:34 +0200, Ingo Molnar wrote:

quoted

* Peter Zijlstra [off-list ref] wrote:

quoted

thinking that that would have my printk stmts appear on both the 
fbcon as well as the serial line. But they fail to appear on the 
latency tracer (current max was 165us waking an idle cpu).

Have you removed this bit:

                spin_unlock(&logbuf_lock);
                stop_critical_timings();        /* don't trace print latency */
                call_console_drivers(_con_start, _log_end);
                start_critical_timings();
                local_irq_restore(flags);

which hides the latencies from the latency tracer?

it shouldn't those flags come from spin_lock_irqsave(), which already
has IRQs disabled, so the restore shouldn't re-enable them.

Hmm,. that might actually already be true for mainline too, yeah, looks
like we call vprintk()->console_unlock() with IRQs-disabled.

Hohumm..

Also, I used the preemptirqoff tracer, so even if it did re-enable
interrupts we should still have preemption disabled and still catch the
latency.

vvOn Fri 2011-06-10 14:30:30, Peter Zijlstra wrote:

On Fri, 2011-06-10 at 13:28 +0200, Peter Zijlstra wrote:

quoted

On Thu, 2011-06-09 at 16:57 -0700, Hugh Dickins wrote:

quoted

All console-related activity curently happens under spin_lock_irqsave(&console_lock). 
This causes interrutps to be blocked for 1-2 milliseconds with vgacon, and for
hundreds of milliseconds with fbdevs.  This results in network overruns, audio
dropouts, dropped characters on serial ports and other such nice things.

Hmm, with these proposed patches we're actually back to that. I wonder
if fbdev is still that crappy..

So I tried adding a fbcon to my test box (not that it actually has a
display, but who cares) and disabled lockdep (otherwise that's all I can
catch on the latency tracer) to see if I could see whopping horrid
latencies there, but I'm afraid I either failed to set things up
properly or my fbcon isn't sucky enough.

What I did was enable:

CONFIG_FB=y
CONFIG_FB_SIS=y
CONFIG_FB_SIS_315=y (the board has XGI z7)

sis will be accelerated. Try vesafb; scrolling should be horrible.
-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html