Re: [patch] Latency Tracer, voluntary-preempt-2.6.8-rc4-O6

Ingo Molnar
2004-08-13T12:01:58Z

* Florian Schmidt <mista.tapas@gmx.net> wrote:

> On Fri, 13 Aug 2004 12:54:06 +0200
> Ingo Molnar <mingo@elte.hu> wrote:
>
> > > (ksoftirqd/0/2): 307 us critical section violates 250 us threshold.
> > > => started at: <___do_softirq+0x20/0x90>
> > > => ended at: <cond_resched_softirq+0x59/0x70>
> >
> > this is too opaque - could you try -O7, enable tracing and save a
> > /proc/latency_trace instance of such a latency? It looks like some
> > sort of softirq latency - perhaps one particular driver's timer fn
> > causes it- we'll be able to tell more from the trace.
>
> Hi, this looks like one of them:
>
> mango:~# cat /proc/latency_trace
> preemption latency trace v1.0
> -----------------------------
> latency: 308 us, entries: 12 (12)
> process: ksoftirqd/0/2, uid: 0
> nice: -10, policy: 0, rt_priority: 0
> =======>
> 0.000ms (+0.000ms): run_timer_softirq (___do_softirq)
> 0.000ms (+0.000ms): sis900_timer (run_timer_softirq)
> 0.001ms (+0.000ms): mdio_read (sis900_timer)
> 0.002ms (+0.000ms): mdio_reset (mdio_read)
> 0.071ms (+0.069ms): mdio_idle (mdio_read)
> 0.151ms (+0.079ms): mdio_read (sis900_timer)
> 0.151ms (+0.000ms): mdio_reset (mdio_read)
> 0.220ms (+0.069ms): mdio_idle (mdio_read)
> 0.300ms (+0.079ms): __mod_timer (sis900_timer)
> 0.300ms (+0.000ms): internal_add_timer (__mod_timer)
> 0.300ms (+0.000ms): cond_resched_softirq (run_timer_softirq)
> 0.301ms (+0.000ms): check_preempt_timing (touch_preempt_timing)

indeed this seems to be a driver related timer: driver/net/sis900.c's
sis900_timer() function. This timer polls your network card for link
status once every second. The mdio_read() function does alot of in/out
instructions which are quite slow.

could you try the following and disable mdio_delay():

#define mdio_delay() do { } while (0)

normally it should work just fine. Worst-case you'd get a non-working
network driver. Does this change reduce the latency?

Ingo