Linux Interrupt Latency benchmark v4 avaible -> detected irq bottleneck before do_bottom_half()
Andrea Arcangeli
my new completely rewritten homepage BTW ;-).
I developed a new very useful feature (to enable with detect=1) in lil-4.
At interrupt time now lil account the eip address where the kernel was
running before to run the irq handler. Then if the latency of the irq
handler is more than 3 times the mean of the latency until that time, lil
will printk the eip address of the kernel code that was running a bit
before to run the interrupt handler.
This new feature has raised that the _only_ point where the kernel is not
interrupt friendly is before the __sti() in do_bottom_half().
And here the numbers:
root@dragon:/home/andrea/devel/irq-latency/lil# insmod ./lil.o irq=3 num=2000000 detect=1
Linux Interrupt Latency benchmark - Copyright (C) 1998 Andrea Arcangeli
detected slow IRQ at: cycle 252593, latency 1653, eip c0117b05, CPU 0
detected slow IRQ at: cycle 254190, latency 2009, eip c0117b05, CPU 0
detected slow IRQ at: cycle 1560602, latency 1914, eip c017c00c, CPU 0
detected slow IRQ at: cycle 1560659, latency 2100, eip c017c00c, CPU 0
latency cycles: mean 542, max 2100, min 542
With 2000000 irq, the mean latency is 542 cycles. The only times the
latency was > than 3*542 the kernel was running at 2 asm instruction after
the sti() in do_bottom_half().
Andrea[s] Arcangeli
-
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majo...@vger.rutgers.edu
Please read the FAQ at http://www.altern.org/andrebalsa/doc/lkml-faq.html
Andrea Arcangeli
>This new feature has raised that the _only_ point where the kernel is not
>interrupt friendly is before the __sti() in do_bottom_half().
>
>And here the numbers:
>
>root@dragon:/home/andrea/devel/irq-latency/lil# insmod ./lil.o irq=3 num=2000000 detect=1
>Linux Interrupt Latency benchmark - Copyright (C) 1998 Andrea Arcangeli
>detected slow IRQ at: cycle 252593, latency 1653, eip c0117b05, CPU 0
>detected slow IRQ at: cycle 254190, latency 2009, eip c0117b05, CPU 0
>detected slow IRQ at: cycle 1560602, latency 1914, eip c017c00c, CPU 0
>detected slow IRQ at: cycle 1560659, latency 2100, eip c017c00c, CPU 0
>latency cycles: mean 542, max 2100, min 542
With an hacked version of lil + patch-ikd with kernel tracer enabled I
exactly discovered what is stalling the irq. It' s the timer irq.
Here the relevant part of the trace:
------------------------------------------------------------------------
Here lil is generating the irq. The way lil generate the irq is this:
cli()
gen irq() (the time of _one_ outb())
sti()
Unfortunately while the irq remains disabled also the timer interrupt
happens and due it s major priority it' s served before.
c2850079 _end +<2663d09/3fe13c8e> (1.88) pid(226) # generating the irq and sti()
c010c0f1 do_IRQ +<d/54> (0.41) pid(226) # run the first irq
c010bfe7 do_8259A_IRQ +<f/9c> (1.76) pid(226)
c010bf00 handle_IRQ_event +<10/64> (0.51) pid(226)
c010f866 pentium_timer_interrupt +<e/d8> (0.48) pid(226) # it' s the timer irq
c0114b11 do_timer +<d/58> (1.24) pid(226)
c010bc55 enable_8259A_irq +<d/38> (0.98) pid(226)
c010c119 do_IRQ +<35/54> (0.35) pid(226) # it' s finisched irq 0
c011b8b3 do_bottom_half +<f/7c> (2.25) pid(226) # irq 0 serve bh handlers
In do_bottom_half() run from irq 0 there is the first __sti() and so
the CPU run the pending irq 3 (lil_irq).
c010c0f1 do_IRQ +<d/54> (0.41) pid(226) # second irq 3 lower priority
c010bfe7 do_8259A_IRQ +<f/9c> (1.76) pid(226)
c010bf00 handle_IRQ_event +<10/64> (0.52) pid(226)
c28500f2 _end +<2663d82/3fe13c8e> (0.64) pid(226) # lil_irq()
c28500c5 _end +<2663d55/3fe13c8e> (1.05) pid(226)
c010bc55 enable_8259A_irq +<d/38> (0.98) pid(226)
c010c119 do_IRQ +<35/54> (0.39) pid(226) # finisched lil_irq()
c011b8b3 do_bottom_half +<f/7c> (0.38) pid(226) # do_bottom_half for irq 3
c010c133 do_IRQ +<4f/54> (0.63) pid(226) # exit irq3 and return in
do_bottom_half() of irq0
Here irq 0 continue to run the pending bh handlers...
c0114793 timer_bh +<13/384> (0.81) pid(226)
c01145d2 update_wall_time +<e/50> (0.33) pid(226)
c01144f5 update_wall_time_one_tick +<d/dc> (0.62) pid(226)
c0114723 update_process_times +<f/6c> (0.46) pid(226)
c0114627 update_one_process +<13/100> (1.20) pid(226)
c0124bf4 swap_tick +<10/ac> (0.32) pid(226)
c012522d free_memory_available +<d/4c> (1.83) pid(226)
c010c133 do_IRQ +<4f/54> (0.70) pid(226) # exit irq 0
c0113c4a del_timer +<e/44> (1.10) pid(226) # return to lil kernel code
c2850226 _end +<2663eb6/3fe13c8e> (1.11) pid(226)
c0116c33 printk +<13/178> (0.88) pid(226) # lil printk that say that lil
has detected a slow irq
So I think there' s really no way to reduce the maximal irq latency (that
happens meanly _once_ after a continuous train of 200000 irq). I don' t
think it' s a good idea to allow the timer interrupt to run with interrupt
enabled.... A _maximal_ latency of ~2557 cycles on a 166Mhz P5noMMX
(15,4uSec) is a very good time I think though... ;-). The mean is 5usec on
the same hardware.
Alexander Kjeldaas
>
> With an hacked version of lil + patch-ikd with kernel tracer enabled I
> exactly discovered what is stalling the irq. It' s the timer irq.
>
>
> So I think there' s really no way to reduce the maximal irq latency (that
> happens meanly _once_ after a continuous train of 200000 irq). I don' t
> think it' s a good idea to allow the timer interrupt to run with interrupt
> enabled.... A _maximal_ latency of ~2557 cycles on a 166Mhz P5noMMX
> (15,4uSec) is a very good time I think though... ;-). The mean is 5usec on
> the same hardware.
>
Hmm.. QNX guarantees 5us latency on a P133 so there _must_ be a way
for us to do better than 20us.
Btw, I ran your module (v3) for 14 hours on a PII233 and got 3.9us min
and 20.3max. The mean calculated by the module couldn't be trusted
because of the integer arithmetic, but from other tests with fewer
interrupts, I think it's very close to the minimum time.
astor
--
Alexander Kjeldaas, Guardian Networks AS, Trondheim, Norway
http://www.guardian.no/
Andrea Arcangeli
>Btw, I ran your module (v3) for 14 hours on a PII233 and got 3.9us min
>and 20.3max. The mean calculated by the module couldn't be trusted
>because of the integer arithmetic, but from other tests with fewer
Yes it can' t be trusted too much.
>interrupts, I think it's very close to the minimum time.
If it' s not precise it doesn' t mean that it has to be very close to the
minimum time per default.
To decrease the max irq latency there are few things to do. You have to
cut the timer irq handler duration (that seems the only thing that harm
here). I don' t think it' s safe to run the irq handler with irq enabled.
If you want to try simply change this line in arch/i386/kernel/time.c
from:
static struct irqaction irq0 = { timer_interrupt, SA_INTERRUPT, 0, "timer", NULL, NULL};
to:
static struct irqaction irq0 = { timer_interrupt, 0, 0, "timer", NULL, NULL};
I am not going to try it ;-).
Andrea[s] Arcangeli