* r8169 (+others ?) and note_interrupt performance hit on 2.6.30.x
@ 2009-07-26 0:31 Michal Soltys
2009-07-26 9:18 ` Francois Romieu
0 siblings, 1 reply; 6+ messages in thread
From: Michal Soltys @ 2009-07-26 0:31 UTC (permalink / raw)
To: netdev
I've noticed, that on 2.6.30 kernels I took serious performance
hit compared to e.g. 2.6.28.10 (didn't check 2.6.29 ones).
Generally, with trivial nc -u other_host </dev/zero
- so ~ 1KB packets and 1gbit speed I went from:
01:30:25 AM CPU %usr %nice %sys %iowait %irq %soft %steal %guest %idle
01:30:26 AM all 0.91 0.00 8.68 0.00 2.28 7.31 0.00 0.00 80.82
01:30:26 AM 0 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
01:30:26 AM 1 1.68 0.00 15.13 0.00 5.04 13.45 0.00 0.00 64.71
running at full 1gbit speed with ease, to:
01:35:26 AM CPU %usr %nice %sys %iowait %irq %soft %steal %guest %idle
01:35:27 AM all 0.50 0.00 12.56 0.00 24.12 12.56 0.00 0.00 50.25
01:35:27 AM 0 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
01:35:27 AM 1 2.00 0.00 25.00 0.00 48.00 25.00 0.00 0.00 0.00
struggling at ~90MB/s (standard pfifo_fast)
Both netcat and interface interrupt were pinned at the same (2nd) core.
I did some quick oprofile, and noticed one new call -
note_interrupt - which wasn't present in the earlier kernel,
taking majority of the cpu time, relatively to the rest, e.g.:
samples cum. samples % cum. % symbol name
90984 90984 42.8695 42.8695 note_interrupt
The hardware is regular 32bit x86:
GA-MA74GM-S2H
AMD 4850e (2.5ghz)
onboard r8169
Both kernels with identical configuration, and tests done on idle machine.
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: r8169 (+others ?) and note_interrupt performance hit on 2.6.30.x
2009-07-26 0:31 r8169 (+others ?) and note_interrupt performance hit on 2.6.30.x Michal Soltys
@ 2009-07-26 9:18 ` Francois Romieu
2009-07-26 10:50 ` Michal Soltys
2009-07-26 18:43 ` Michal Soltys
0 siblings, 2 replies; 6+ messages in thread
From: Francois Romieu @ 2009-07-26 9:18 UTC (permalink / raw)
To: Michal Soltys; +Cc: netdev
Michal Soltys <soltys@ziu.info> :
[...]
> I did some quick oprofile, and noticed one new call -
> note_interrupt - which wasn't present in the earlier kernel,
> taking majority of the cpu time, relatively to the rest, e.g.:
>
> samples cum. samples % cum. % symbol name
> 90984 90984 42.8695 42.8695 note_interrupt
May be some screaming irq.
Do your /proc/interrupts look the same with both kernels ?
--
Ueimor
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: r8169 (+others ?) and note_interrupt performance hit on 2.6.30.x
2009-07-26 9:18 ` Francois Romieu
@ 2009-07-26 10:50 ` Michal Soltys
2009-07-26 18:43 ` Michal Soltys
1 sibling, 0 replies; 6+ messages in thread
From: Michal Soltys @ 2009-07-26 10:50 UTC (permalink / raw)
To: Francois Romieu; +Cc: netdev
Francois Romieu wrote:
> Michal Soltys <soltys@ziu.info> :
> [...]
>> I did some quick oprofile, and noticed one new call -
>> note_interrupt - which wasn't present in the earlier kernel,
>> taking majority of the cpu time, relatively to the rest, e.g.:
>>
>> samples cum. samples % cum. % symbol name
>> 90984 90984 42.8695 42.8695 note_interrupt
>
> May be some screaming irq.
>
> Do your /proc/interrupts look the same with both kernels ?
>
Yes - nothing unusual there, and amount of interrupts on the interface
corresponds to pps. The rest is roughly idle.
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: r8169 (+others ?) and note_interrupt performance hit on 2.6.30.x
2009-07-26 9:18 ` Francois Romieu
2009-07-26 10:50 ` Michal Soltys
@ 2009-07-26 18:43 ` Michal Soltys
2009-07-27 21:52 ` Jarek Poplawski
1 sibling, 1 reply; 6+ messages in thread
From: Michal Soltys @ 2009-07-26 18:43 UTC (permalink / raw)
To: Francois Romieu; +Cc: netdev
I did some more tests, with kernel booted both with noirqdebug and
without (as this decides if note_interrupt gets called from
handle_edge_irq).
As far as cpu load goes, everything remained the same - 100% on chosen
core, unable to reach 1gbit. When noirqdebug was enabled, oprofile showed
majority of time spent in handle_edge_irq:
CPU: AMD64 processors, speed 2517.35 MHz (estimated)
Counted CPU_CLK_UNHALTED events (Cycles outside of halt state) with a unit mask of 0x00 (No unit mask) count 50000
samples cum. samples % cum. % symbol name
15238 15238 38.1723 38.1723 handle_edge_irq
2146 17384 5.3759 43.5482 rb_get_reader_page
1877 19261 4.7020 48.2502 csum_partial_copy_generic
1671 20932 4.1860 52.4362 getnstimeofday
1618 22550 4.0532 56.4894 udp_sendmsg
1366 23916 3.4219 59.9113 ip_append_data
1159 25075 2.9034 62.8147 ring_buffer_consume
1153 26228 2.8883 65.7030 handle_IRQ_event
779 27007 1.9515 67.6545 __kmalloc_track_caller
... and with callgraph:
CPU: AMD64 processors, speed 2517.35 MHz (estimated)
Counted CPU_CLK_UNHALTED events (Cycles outside of halt state) with a unit mask of 0x00 (No unit mask) count 50000
samples cum. samples % cum. % symbol name
-------------------------------------------------------------------------------
1 1 0.0030 0.0030 vmlinux-test do_IRQ
1 2 0.0030 0.0060 vmlinux-test sock_poll
1 3 0.0030 0.0090 vmlinux-test net_rx_action
2 5 0.0060 0.0149 vmlinux-test do_softirq
2 7 0.0060 0.0209 vmlinux-test op_add_code
3 10 0.0090 0.0298 vmlinux-test handle_IRQ_event
12 22 0.0358 0.0657 vmlinux-test inet_sendmsg
13 35 0.0388 0.1045 vmlinux-test sk_filter
39 74 0.1164 0.2209 vmlinux-test ktime_get_real
61 135 0.1821 0.4029 vmlinux-test log_sample
104 239 0.3104 0.7133 vmlinux-test x86_backtrace
15178 15417 45.2993 46.0127 vmlinux-test handle_edge_irq
18089 33506 53.9873 100.000 vmlinux-test handle_irq
15238 15238 38.1723 38.1723 vmlinux-test handle_edge_irq
15238 15238 45.4404 45.4404 vmlinux-test handle_edge_irq [self]
15178 30416 45.2615 90.7020 vmlinux-test handle_edge_irq
2833 33249 8.4481 99.1501 vmlinux-test handle_IRQ_event
166 33415 0.4950 99.6451 vmlinux-test udp_sendmsg
42 33457 0.1252 99.7704 vmlinux-test ack_apic_edge
39 33496 0.1163 99.8867 vmlinux-test getnstimeofday
8 33504 0.0239 99.9105 r8169.ko rtl8169_poll
7 33511 0.0209 99.9314 vmlinux-test do_IRQ
5 33516 0.0149 99.9463 vmlinux-test __pollwait
5 33521 0.0149 99.9612 vmlinux-test log_sample
5 33526 0.0149 99.9761 r8169.ko rtl8169_interrupt
2 33528 0.0060 99.9821 vmlinux-test __do_softirq
1 33529 0.0030 99.9851 vmlinux-test sk_run_filter
1 33530 0.0030 99.9881 vmlinux-test udp_poll
1 33531 0.0030 99.9911 vmlinux-test op_add_code
1 33532 0.0030 99.9940 vmlinux-test x86_backtrace
1 33533 0.0030 99.9970 vmlinux-test _spin_lock
1 33534 0.0030 100.000 vmlinux-test apic_timer_interrupt
-------------------------------------------------------------------------------
Additional note - with noirqdebug, I often had to sync and reboot through sysreq.
Without noirqdebug, oprofile showed:
CPU: AMD64 processors, speed 2517.14 MHz (estimated)
Counted CPU_CLK_UNHALTED events (Cycles outside of halt state) with a unit mask of 0x00 (No unit mask) count 50000
samples cum. samples % cum. % symbol name
24056 24056 63.5108 63.5108 note_interrupt
3415 27471 9.0160 72.5269 rb_get_reader_page
1633 29104 4.3113 76.8382 ring_buffer_consume
728 29832 1.9220 78.7602 add_event_entry
681 30513 1.7979 80.5581 rb_buffer_peek
621 31134 1.6395 82.1976 getnstimeofday
[...]
29 36831 0.0766 97.2384 handle_edge_irq
... and with callgraph:
CPU: AMD64 processors, speed 2517.14 MHz (estimated)
Counted CPU_CLK_UNHALTED events (Cycles outside of halt state) with a unit mask of 0x00 (No unit mask) count 50000
samples cum. samples % cum. % image name symbol name
-------------------------------------------------------------------------------
1 1 0.0041 0.0041 vmlinux-test do_timer
10 11 0.0414 0.0456 vmlinux-test inet_sendmsg
26 37 0.1077 0.1533 vmlinux-test timer_start
43 80 0.1782 0.3315 vmlinux-test _spin_lock_bh
24054 24134 99.6685 100.000 vmlinux-test handle_edge_irq
24056 24056 63.5108 63.5108 vmlinux-test note_interrupt
24056 24056 99.6644 99.6644 vmlinux-test note_interrupt [self]
44 24100 0.1823 99.8467 vmlinux-test __pollwait
37 24137 0.1533 100.000 vmlinux-test dump_trace
-------------------------------------------------------------------------------
[...]
-------------------------------------------------------------------------------
1 1 0.0039 0.0039 vmlinux-test do_softirq
1 2 0.0039 0.0079 vmlinux-test irq_exit
1 3 0.0039 0.0118 vmlinux-test sock_def_write_space
3 6 0.0118 0.0236 vmlinux-test net_rx_action
3 9 0.0118 0.0354 vmlinux-test sk_filter
5 14 0.0197 0.0551 vmlinux-test do_IRQ
8 22 0.0315 0.0865 vmlinux-test handle_edge_irq
10 32 0.0393 0.1259 vmlinux-test ktime_get_real
25389 25421 99.8741 100.000 vmlinux-test handle_irq
29 36831 0.0766 97.2384 vmlinux-test handle_edge_irq
24054 24054 94.5742 94.5742 vmlinux-test note_interrupt
1286 25340 5.0562 99.6304 vmlinux-test handle_IRQ_event
29 25369 0.1140 99.7444 vmlinux-test handle_edge_irq [self]
18 25387 0.0708 99.8152 vmlinux-test ack_apic_edge
15 25402 0.0590 99.8742 r8169.ko rtl8169_poll
10 25412 0.0393 99.9135 vmlinux-test getnstimeofday
8 25420 0.0315 99.9450 vmlinux-test handle_edge_irq
4 25424 0.0157 99.9607 vmlinux-test apic_timer_interrupt
3 25427 0.0118 99.9725 r8169.ko rtl8169_interrupt
2 25429 0.0079 99.9803 r8169.ko rtl8169_rx_interrupt
1 25430 0.0039 99.9843 vmlinux-test __do_softirq
1 25431 0.0039 99.9882 vmlinux-test move_native_irq
1 25432 0.0039 99.9921 vmlinux-test sk_run_filter
1 25433 0.0039 99.9961 vmlinux-test __pollwait
1 25434 0.0039 100.000 ip_tables.ko ipt_do_table
-------------------------------------------------------------------------------
From a breif look over the above, rtl8169_rx_interrupt
is not called in noirqdebug case, and handle_edge_irq gets called
from within handle_edge_irq ?
Anwyay, not sure if this is useful, so if there is anything better
I could do, just push me in the right direction.
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: r8169 (+others ?) and note_interrupt performance hit on 2.6.30.x
2009-07-26 18:43 ` Michal Soltys
@ 2009-07-27 21:52 ` Jarek Poplawski
2009-08-05 18:54 ` Michal Soltys
0 siblings, 1 reply; 6+ messages in thread
From: Jarek Poplawski @ 2009-07-27 21:52 UTC (permalink / raw)
To: Michal Soltys; +Cc: Francois Romieu, netdev
Michal Soltys wrote, On 07/26/2009 08:43 PM:
...
> Anwyay, not sure if this is useful, so if there is anything better
> I could do, just push me in the right direction.
Short test of 2.6.29? (Unless you prefer a bisection...)
Jarek P.
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: r8169 (+others ?) and note_interrupt performance hit on 2.6.30.x
2009-07-27 21:52 ` Jarek Poplawski
@ 2009-08-05 18:54 ` Michal Soltys
0 siblings, 0 replies; 6+ messages in thread
From: Michal Soltys @ 2009-08-05 18:54 UTC (permalink / raw)
To: netdev; +Cc: Jarek Poplawski, Francois Romieu
Jarek Poplawski wrote:
> Michal Soltys wrote, On 07/26/2009 08:43 PM:
>
> ...
>> Anwyay, not sure if this is useful, so if there is anything better
>> I could do, just push me in the right direction.
>
> Short test of 2.6.29? (Unless you prefer a bisection...)
>
> Jarek P.
> --
> To unsubscribe from this list: send the line "unsubscribe netdev" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at http://vger.kernel.org/majordomo-info.html
>
I did first bisection, and the whole cpu load increases seem a bit more
complicated than I originally thought.
I noticed at least 2 (possibly 3) moments where it increased (from
original full 1 gbit at 20% - 50% load of one core)
(1) jump from 20% - 50% to 80% - 90%
(2) commit f11a377b3f4e897d11f0e8d1fc688667e2f19708
r8169: avoid losing MSI interrupts
After the above commit, one core is not enough to handle 1 gbit speed
with 1k packets, it ends with with ~760mbit and one core drained at 100%
. The situation right before this commit is as in (1)
All tests were done, as mentioned earlier - with nc process and eth
interrupts pinned to the same core, and besides nc process - idle
machine. Tested with udp only, standard pfifo_fast.
The changes happened between 2.6.29 and 2.6.30-rc6 .
I'll try to pinpoint when (1) happens now. Lookint at mpstat output,
those may actually be two different commits.
^ permalink raw reply [flat|nested] 6+ messages in thread
end of thread, other threads:[~2009-08-05 18:54 UTC | newest]
Thread overview: 6+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2009-07-26 0:31 r8169 (+others ?) and note_interrupt performance hit on 2.6.30.x Michal Soltys
2009-07-26 9:18 ` Francois Romieu
2009-07-26 10:50 ` Michal Soltys
2009-07-26 18:43 ` Michal Soltys
2009-07-27 21:52 ` Jarek Poplawski
2009-08-05 18:54 ` Michal Soltys
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).