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

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

[Peter Zijlstra]

On Fri, 2011-06-10 at 13:28 +0200, Peter Zijlstra wrote:
> On Thu, 2011-06-09 at 16:57 -0700, Hugh Dickins wrote:
> > 
> > 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?

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

[Ingo Molnar]

* Peter Zijlstra <peterz@infradead.org> 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

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

[Peter Zijlstra]

On Fri, 2011-06-10 at 14:34 +0200, Ingo Molnar wrote:
> * Peter Zijlstra <peterz@infradead.org> 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?

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..

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

[Peter Zijlstra]

On Fri, 2011-06-10 at 14:41 +0200, Peter Zijlstra wrote:
> On Fri, 2011-06-10 at 14:34 +0200, Ingo Molnar wrote:
> > * Peter Zijlstra <peterz@infradead.org> 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?
> 
> 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.

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

[Pavel Machek]

vvOn Fri 2011-06-10 14:30:30, Peter Zijlstra wrote:
>On Fri, 2011-06-10 at 13:28 +0200, Peter Zijlstra wrote:
> > On Thu, 2011-06-09 at 16:57 -0700, Hugh Dickins wrote:
> > > 
> > > 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