Re: Loopback performance from kernel 2.6.12 to 2.6.37

Re: Loopback performance from kernel 2.6.12 to 2.6.37

[Xose Vazquez Perez]

Jesper Dangaard Brouer wrote:

> To fix this I added "-q 0" to netcat.  Thus my working commands are:
> 
>  netcat -l -p 9999 >/dev/null &
>  time dd if=/dev/zero bs=1M count=10000 | netcat -q0 127.0.0.1 9999
> 
> Running this on my "big" 10G testlab system, Dual Xeon 5550 2.67GHz,
> kernel version 2.6.32-5-amd64 (which I usually don't use)
> The results are 7.487 sec:

netcat flavor ?

http://nc110.sourceforge.net/
http://nmap.org/ncat/
http://www.dest-unreach.org/socat/
http://cryptcat.sourceforge.net/
http://netcat.sourceforge.net/
http://www.openbsd.org/cgi-bin/cvsweb/src/usr.bin/nc/

-- 
«Allá muevan feroz guerra, ciegos reyes por un palmo más de tierra;
que yo aquí tengo por mío cuanto abarca el mar bravío, a quien nadie
impuso leyes. Y no hay playa, sea cualquiera, ni bandera de esplendor,
que no sienta mi derecho y dé pecho a mi valor.»

Re: Loopback performance from kernel 2.6.12 to 2.6.37

[Jesper Dangaard Brouer]

On Tue, 2010-11-09 at 22:35 +0100, Xose Vazquez Perez wrote:
> Jesper Dangaard Brouer wrote:
> 
> > To fix this I added "-q 0" to netcat.  Thus my working commands are:
> > 
> >  netcat -l -p 9999 >/dev/null &
> >  time dd if=/dev/zero bs=1M count=10000 | netcat -q0 127.0.0.1 9999
> > 
> > Running this on my "big" 10G testlab system, Dual Xeon 5550 2.67GHz,
> > kernel version 2.6.32-5-amd64 (which I usually don't use)
> > The results are 7.487 sec:
> 
> netcat flavor ?

Debian package netcat-traditional
 netcat version [v1.10-38]

>From "aptitude show netcat-traditional":
 This is the "classic" netcat, written by *Hobbit*. It lacks many
features found in netcat-openbsd.

Didn't know there were that many flavors...

> http://nc110.sourceforge.net/
> http://nmap.org/ncat/
> http://www.dest-unreach.org/socat/
> http://cryptcat.sourceforge.net/
> http://netcat.sourceforge.net/
> http://www.openbsd.org/cgi-bin/cvsweb/src/usr.bin/nc/


-- 
Med venlig hilsen / Best regards
  Jesper Brouer
  ComX Networks A/S
  Linux Network Kernel Developer
  Cand. Scient Datalog / MSc.CS
  Author of http://adsl-optimizer.dk
  LinkedIn: http://www.linkedin.com/in/brouer

Re: Loopback performance from kernel 2.6.12 to 2.6.37

[Eric Dumazet]

Le lundi 08 novembre 2010 à 12:04 +0100, Eric Dumazet a écrit :
> Le lundi 08 novembre 2010 à 11:58 +0100, Jesper Dangaard Brouer a
> écrit :
> > On Fri, 2010-11-05 at 21:29 +0100, Eric Dumazet wrote:
> > > Le vendredi 05 novembre 2010 à 11:49 +0100, Jesper Dangaard Brouer a
> > > écrit :
> > > > Hi Eric,
> > > > 
> > > > A colleague send me a link to someone who has done some quite extensive
> > > > performance measurements across different kernel versions.
> > > > 
> > > > I noticed that the loopback performance has gotten quite bad:
> > > > 
> > > > http://www.phoronix.com/scan.php?page=article&item=linux_2612_2637&num=6
> > > > 
> > > > I though you might be interested in the link.
> > > > 
> > > > See you around :-)
> > > 
> > > Hi !
> > > 
> > > Problem is : I have no idea what test they exactly use,
> > > do you have info about it ?
> > 
> > Its called the Phoronix test-suite, their website is:
> > http://www.phoronix-test-suite.com/?k=home
> > 
> > On my Ubuntu workstation their software comes as a software package:
> >  sudo aptitude install phoronix-test-suite
> > 
> > They seem to be related to the test/review site:
> > http://www.phoronix.com/
> > 
> > 
> > 
> > > This probably can be explained very fast.
> > 
> > The loopback test seems to be the only real networking test they do.
> > It looks like they just copy a very big fil via loopback, and record the
> > time it took... quite simple.
> > 
> > Their tests seems to be focused on CPU util/speed, graphics/games.
> > 
> > 
> > The thing that caught my attention, was that they seemed interested in
> > doing performance regression testing on all kernel versions...
> > 
> > So, I though, it would be great if someone else would do automated
> > performance regression testing for us :-),  Too bad they only have a
> > very simple network test.
> > 
> > 
> 

> 

CC netdev, if you dont mind.


Their network test is basically :

netcat -l 9999 >/dev/null &
time dd if=/dev/zero bs=1M count=10000 | netcat  127.0.0.1 9999

They say it takes 38 seconds on their "super fast" processor

On my dev machine, not super fast (E5540 @2.53GHz), I get 8 or 9
seconds, even if only one CPU is online, all others offline.

Go figure... maybe an artifact of the virtualization they use.

I suspect some problem with the ticket spinlocks and a call to
hypervisor to say 'I am spinning on a spinlock, see if you need to do
something useful', or maybe ACPI problem (going to/from idle)

Re: Loopback performance from kernel 2.6.12 to 2.6.37

[Andrew Hendry]

results on an i7 860 @ 2.80Ghz machine, no virtualization involved. 2.6.37-rc1+

# time dd if=/dev/zero bs=1M count=10000 | netcat  127.0.0.1 9999
10000+0 records in
10000+0 records out
10485760000 bytes (10 GB) copied, 50.2022 s, 209 MB/s

real	0m50.210s
user	0m1.094s
sys	0m57.589s



On Tue, Nov 9, 2010 at 2:06 AM, Eric Dumazet <eric.dumazet@gmail.com> wrote:
> Le lundi 08 novembre 2010 à 12:04 +0100, Eric Dumazet a écrit :
>> Le lundi 08 novembre 2010 à 11:58 +0100, Jesper Dangaard Brouer a
>> écrit :
>> > On Fri, 2010-11-05 at 21:29 +0100, Eric Dumazet wrote:
>> > > Le vendredi 05 novembre 2010 à 11:49 +0100, Jesper Dangaard Brouer a
>> > > écrit :
>> > > > Hi Eric,
>> > > >
>> > > > A colleague send me a link to someone who has done some quite extensive
>> > > > performance measurements across different kernel versions.
>> > > >
>> > > > I noticed that the loopback performance has gotten quite bad:
>> > > >
>> > > > http://www.phoronix.com/scan.php?page=article&item=linux_2612_2637&num=6
>> > > >
>> > > > I though you might be interested in the link.
>> > > >
>> > > > See you around :-)
>> > >
>> > > Hi !
>> > >
>> > > Problem is : I have no idea what test they exactly use,
>> > > do you have info about it ?
>> >
>> > Its called the Phoronix test-suite, their website is:
>> > http://www.phoronix-test-suite.com/?k=home
>> >
>> > On my Ubuntu workstation their software comes as a software package:
>> >  sudo aptitude install phoronix-test-suite
>> >
>> > They seem to be related to the test/review site:
>> > http://www.phoronix.com/
>> >
>> >
>> >
>> > > This probably can be explained very fast.
>> >
>> > The loopback test seems to be the only real networking test they do.
>> > It looks like they just copy a very big fil via loopback, and record the
>> > time it took... quite simple.
>> >
>> > Their tests seems to be focused on CPU util/speed, graphics/games.
>> >
>> >
>> > The thing that caught my attention, was that they seemed interested in
>> > doing performance regression testing on all kernel versions...
>> >
>> > So, I though, it would be great if someone else would do automated
>> > performance regression testing for us :-),  Too bad they only have a
>> > very simple network test.
>> >
>> >
>>
>
>>
>
> CC netdev, if you dont mind.
>
>
> Their network test is basically :
>
> netcat -l 9999 >/dev/null &
> time dd if=/dev/zero bs=1M count=10000 | netcat  127.0.0.1 9999
>
> They say it takes 38 seconds on their "super fast" processor
>
> On my dev machine, not super fast (E5540 @2.53GHz), I get 8 or 9
> seconds, even if only one CPU is online, all others offline.
>
> Go figure... maybe an artifact of the virtualization they use.
>
> I suspect some problem with the ticket spinlocks and a call to
> hypervisor to say 'I am spinning on a spinlock, see if you need to do
> something useful', or maybe ACPI problem (going to/from idle)
>
>
>
>
> --
> 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
>

Re: Loopback performance from kernel 2.6.12 to 2.6.37

[Eric Dumazet]

Le mardi 09 novembre 2010 à 11:05 +1100, Andrew Hendry a écrit :
> results on an i7 860 @ 2.80Ghz machine, no virtualization involved. 2.6.37-rc1+
> 
> # time dd if=/dev/zero bs=1M count=10000 | netcat  127.0.0.1 9999
> 10000+0 records in
> 10000+0 records out
> 10485760000 bytes (10 GB) copied, 50.2022 s, 209 MB/s
> 
> real	0m50.210s
> user	0m1.094s
> sys	0m57.589s

Thanks !

Could you take a pef snapshot during the test ?

# perf record -a -g sleep 10
# perf report

Re: Loopback performance from kernel 2.6.12 to 2.6.37

[Eric Dumazet]

Le mardi 09 novembre 2010 à 06:22 +0100, Eric Dumazet a écrit :
> Le mardi 09 novembre 2010 à 11:05 +1100, Andrew Hendry a écrit :
> > results on an i7 860 @ 2.80Ghz machine, no virtualization involved. 2.6.37-rc1+
> > 
> > # time dd if=/dev/zero bs=1M count=10000 | netcat  127.0.0.1 9999
> > 10000+0 records in
> > 10000+0 records out
> > 10485760000 bytes (10 GB) copied, 50.2022 s, 209 MB/s
> > 
> > real	0m50.210s
> > user	0m1.094s
> > sys	0m57.589s
> 
> Thanks !
> 
> Could you take a pef snapshot during the test ?
> 
> # perf record -a -g sleep 10
> # perf report
> 
> 

On my laptop 
Intel(R) Core(TM)2 Duo CPU     T8300  @ 2.40GHz
(2.6.35-22-generic #35-Ubuntu SMP Sat Oct 16 20:45:36 UTC 2010 x86_64
GNU/Linux) :

time dd if=/dev/zero bs=1M count=10000|netcat 127.0.0.1 9999
10000+0 enregistrements lus
10000+0 enregistrements écrits
10485760000 octets (10 GB) copiés, 38,2691 s, 274 MB/s

real	0m38.274s
user	0m1.870s
sys	0m38.370s


perf top result :

-------------------------------------------------------------------------------------------------
   PerfTop:    1948 irqs/sec  kernel:90.7%  exact:  0.0% [1000Hz cycles],  (all, 2 CPUs)
-------------------------------------------------------------------------------------------------

             samples  pcnt function                    DSO
             _______ _____ ___________________________ ___________________

             1867.00 12.4% copy_user_generic_string    [kernel.kallsyms]  
             1166.00  7.7% __ticket_spin_lock          [kernel.kallsyms]  
              744.00  4.9% __clear_user                [kernel.kallsyms]  
              667.00  4.4% system_call                 [kernel.kallsyms]  
              329.00  2.2% tcp_sendmsg                 [kernel.kallsyms]  
              304.00  2.0% schedule                    [kernel.kallsyms]  
              257.00  1.7% _raw_spin_unlock_irqrestore [kernel.kallsyms]  
              231.00  1.5% fget_light                  [kernel.kallsyms]  
              216.00  1.4% do_poll                     [kernel.kallsyms]  
              203.00  1.3% __read_chk                  /lib/libc-2.12.1.so
              202.00  1.3% __pollwait                  [kernel.kallsyms]  
              201.00  1.3% __poll                      /lib/libc-2.12.1.so
              187.00  1.2% system_call_after_swapgs    [kernel.kallsyms]  
              176.00  1.2% __write                     /lib/libc-2.12.1.so
              173.00  1.1% _raw_spin_lock_irqsave      [kernel.kallsyms]  
              163.00  1.1% tcp_recvmsg                 [kernel.kallsyms]  
              158.00  1.0% do_sys_poll                 [kernel.kallsyms]  
              153.00  1.0% vfs_write                   [kernel.kallsyms]  
              143.00  0.9% pipe_read                   [kernel.kallsyms]  
              141.00  0.9% fput                        [kernel.kallsyms]  
              121.00  0.8% common_file_perm            [kernel.kallsyms]  
              120.00  0.8% _cond_resched               [kernel.kallsyms]  


# vmstat 1
procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa
 2  0   1456 120056  51572 2606876    0    0   158    41  254  190  9  2 88  0
 2  0   1456 120140  51580 2606868    0    0    12     0  758 158309 11 76 13  0
 2  0   1456 119520  51588 2606896    0    0     0   176  778 160749  8 80 12  0
 2  0   1456 120388  51588 2606896    0    0     0     0  730 158201  9 76 16  0
 3  0   1456 120388  51588 2606896    0    0     0     0  745 158490  8 76 16  0
 2  0   1456 120520  51588 2606896    0    0     0     0  991 159120  9 78 13  0
 2  0   1456 120024  51588 2606896    0    0     0     0  653 160023 10 79 11  0
 3  0   1456 120520  51588 2606896    0    0     0     0  659 160614  8 78 14  0
 2  0   1456 120272  51596 2606896    0    0     0    80  695 159922 10 75 14  0
 4  0   1456 120272  51596 2606896    0    0     0     0  675 158010  7 79 14  0


# powertop
     PowerTOP version 1.13      (C) 2007 Intel Corporation

< Detailed C-state information is not P-states (frequencies)
                                      Turbo Mode    43.1%
                                        2.40 Ghz    48.0%
                                        2.00 Ghz     8.2%
                                        1.60 Ghz     0.7%
                                        1200 Mhz     0.1%

Wakeups-from-idle per second : 542.9    interval: 10.0s
no ACPI power usage estimate available

Top causes for wakeups:
  21.9% (196.5)   [kernel scheduler] Load balancing tick
  21.2% (190.7)   [Rescheduling interrupts] <kernel IPI>
  12.7% (114.0)   PS/2 keyboard/mouse/touchpad interrupt
  12.0% (107.9)   plugin-containe
  11.1% ( 99.3)   alsa-sink
   6.0% ( 53.8)   firefox-bin
   4.4% ( 39.7)   fping
   3.9% ( 35.2)   Xorg
   1.3% ( 11.3)   [b43] <interrupt>
   1.1% ( 10.0)   ksoftirqd/0
   0.4% (  4.0)D  nagios3
   0.2% (  1.9)D  gnome-terminal
   0.7% (  6.4)   [Thermal event interrupts] <kernel IPI>

Re: Loopback performance from kernel 2.6.12 to 2.6.37

[Andrew Hendry]

most my slowdown was kmemleak left on.

After fixing its is still a lot slower than your dev system
.
# time dd if=/dev/zero bs=1M count=10000 | netcat  127.0.0.1 9999
10000+0 records in
10000+0 records out
10485760000 bytes (10 GB) copied, 25.8182 s, 406 MB/s

real	0m25.821s
user	0m1.502s
sys	0m33.463s

------------------------------------------------------------------------------------------------------------------
   PerfTop:     241 irqs/sec  kernel:56.8%  exact:  0.0% [1000Hz
cycles],  (all, 8 CPUs)
------------------------------------------------------------------------------------------------------------------

             samples  pcnt function                    DSO
             _______ _____ ___________________________
______________________________________

             1255.00  8.7% hpet_msi_next_event
/lib/modules/2.6.37-rc1+/build/vmlinux
             1081.00  7.5% copy_user_generic_string
/lib/modules/2.6.37-rc1+/build/vmlinux
              863.00  6.0% __ticket_spin_lock
/lib/modules/2.6.37-rc1+/build/vmlinux
              498.00  3.5% do_sys_poll
/lib/modules/2.6.37-rc1+/build/vmlinux
              455.00  3.2% system_call
/lib/modules/2.6.37-rc1+/build/vmlinux
              409.00  2.8% fget_light
/lib/modules/2.6.37-rc1+/build/vmlinux
              348.00  2.4% tcp_sendmsg
/lib/modules/2.6.37-rc1+/build/vmlinux
              269.00  1.9% fsnotify
/lib/modules/2.6.37-rc1+/build/vmlinux
              258.00  1.8% _raw_spin_unlock_irqrestore
/lib/modules/2.6.37-rc1+/build/vmlinux
              223.00  1.6% _raw_spin_lock_irqsave
/lib/modules/2.6.37-rc1+/build/vmlinux
              203.00  1.4% __clear_user
/lib/modules/2.6.37-rc1+/build/vmlinux
              184.00  1.3% tcp_poll
/lib/modules/2.6.37-rc1+/build/vmlinux
              178.00  1.2% vfs_write
/lib/modules/2.6.37-rc1+/build/vmlinux
              165.00  1.1% tcp_recvmsg
/lib/modules/2.6.37-rc1+/build/vmlinux
              152.00  1.1% pipe_read
/lib/modules/2.6.37-rc1+/build/vmlinux
              149.00  1.0% schedule
/lib/modules/2.6.37-rc1+/build/vmlinux
              135.00  0.9% rw_verify_area
/lib/modules/2.6.37-rc1+/build/vmlinux
              135.00  0.9% __pollwait
/lib/modules/2.6.37-rc1+/build/vmlinux
              130.00  0.9% __write
/lib/libc-2.12.1.so
              127.00  0.9% __ticket_spin_unlock
/lib/modules/2.6.37-rc1+/build/vmlinux
              126.00  0.9% __poll
/lib/libc-2.12.1.so


On Tue, Nov 9, 2010 at 5:23 PM, Eric Dumazet <eric.dumazet@gmail.com> wrote:
> Le mardi 09 novembre 2010 à 06:22 +0100, Eric Dumazet a écrit :
>> Le mardi 09 novembre 2010 à 11:05 +1100, Andrew Hendry a écrit :
>> > results on an i7 860 @ 2.80Ghz machine, no virtualization involved. 2.6.37-rc1+
>> >
>> > # time dd if=/dev/zero bs=1M count=10000 | netcat  127.0.0.1 9999
>> > 10000+0 records in
>> > 10000+0 records out
>> > 10485760000 bytes (10 GB) copied, 50.2022 s, 209 MB/s
>> >
>> > real        0m50.210s
>> > user        0m1.094s
>> > sys 0m57.589s
>>
>> Thanks !
>>
>> Could you take a pef snapshot during the test ?
>>
>> # perf record -a -g sleep 10
>> # perf report
>>
>>
>
> On my laptop
> Intel(R) Core(TM)2 Duo CPU     T8300  @ 2.40GHz
> (2.6.35-22-generic #35-Ubuntu SMP Sat Oct 16 20:45:36 UTC 2010 x86_64
> GNU/Linux) :
>
> time dd if=/dev/zero bs=1M count=10000|netcat 127.0.0.1 9999
> 10000+0 enregistrements lus
> 10000+0 enregistrements écrits
> 10485760000 octets (10 GB) copiés, 38,2691 s, 274 MB/s
>
> real    0m38.274s
> user    0m1.870s
> sys     0m38.370s
>
>
> perf top result :
>
> -------------------------------------------------------------------------------------------------
>   PerfTop:    1948 irqs/sec  kernel:90.7%  exact:  0.0% [1000Hz cycles],  (all, 2 CPUs)
> -------------------------------------------------------------------------------------------------
>
>             samples  pcnt function                    DSO
>             _______ _____ ___________________________ ___________________
>
>             1867.00 12.4% copy_user_generic_string    [kernel.kallsyms]
>             1166.00  7.7% __ticket_spin_lock          [kernel.kallsyms]
>              744.00  4.9% __clear_user                [kernel.kallsyms]
>              667.00  4.4% system_call                 [kernel.kallsyms]
>              329.00  2.2% tcp_sendmsg                 [kernel.kallsyms]
>              304.00  2.0% schedule                    [kernel.kallsyms]
>              257.00  1.7% _raw_spin_unlock_irqrestore [kernel.kallsyms]
>              231.00  1.5% fget_light                  [kernel.kallsyms]
>              216.00  1.4% do_poll                     [kernel.kallsyms]
>              203.00  1.3% __read_chk                  /lib/libc-2.12.1.so
>              202.00  1.3% __pollwait                  [kernel.kallsyms]
>              201.00  1.3% __poll                      /lib/libc-2.12.1.so
>              187.00  1.2% system_call_after_swapgs    [kernel.kallsyms]
>              176.00  1.2% __write                     /lib/libc-2.12.1.so
>              173.00  1.1% _raw_spin_lock_irqsave      [kernel.kallsyms]
>              163.00  1.1% tcp_recvmsg                 [kernel.kallsyms]
>              158.00  1.0% do_sys_poll                 [kernel.kallsyms]
>              153.00  1.0% vfs_write                   [kernel.kallsyms]
>              143.00  0.9% pipe_read                   [kernel.kallsyms]
>              141.00  0.9% fput                        [kernel.kallsyms]
>              121.00  0.8% common_file_perm            [kernel.kallsyms]
>              120.00  0.8% _cond_resched               [kernel.kallsyms]
>
>
> # vmstat 1
> procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu----
>  r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa
>  2  0   1456 120056  51572 2606876    0    0   158    41  254  190  9  2 88  0
>  2  0   1456 120140  51580 2606868    0    0    12     0  758 158309 11 76 13  0
>  2  0   1456 119520  51588 2606896    0    0     0   176  778 160749  8 80 12  0
>  2  0   1456 120388  51588 2606896    0    0     0     0  730 158201  9 76 16  0
>  3  0   1456 120388  51588 2606896    0    0     0     0  745 158490  8 76 16  0
>  2  0   1456 120520  51588 2606896    0    0     0     0  991 159120  9 78 13  0
>  2  0   1456 120024  51588 2606896    0    0     0     0  653 160023 10 79 11  0
>  3  0   1456 120520  51588 2606896    0    0     0     0  659 160614  8 78 14  0
>  2  0   1456 120272  51596 2606896    0    0     0    80  695 159922 10 75 14  0
>  4  0   1456 120272  51596 2606896    0    0     0     0  675 158010  7 79 14  0
>
>
> # powertop
>     PowerTOP version 1.13      (C) 2007 Intel Corporation
>
> < Detailed C-state information is not P-states (frequencies)
>                                      Turbo Mode    43.1%
>                                        2.40 Ghz    48.0%
>                                        2.00 Ghz     8.2%
>                                        1.60 Ghz     0.7%
>                                        1200 Mhz     0.1%
>
> Wakeups-from-idle per second : 542.9    interval: 10.0s
> no ACPI power usage estimate available
>
> Top causes for wakeups:
>  21.9% (196.5)   [kernel scheduler] Load balancing tick
>  21.2% (190.7)   [Rescheduling interrupts] <kernel IPI>
>  12.7% (114.0)   PS/2 keyboard/mouse/touchpad interrupt
>  12.0% (107.9)   plugin-containe
>  11.1% ( 99.3)   alsa-sink
>   6.0% ( 53.8)   firefox-bin
>   4.4% ( 39.7)   fping
>   3.9% ( 35.2)   Xorg
>   1.3% ( 11.3)   [b43] <interrupt>
>   1.1% ( 10.0)   ksoftirqd/0
>   0.4% (  4.0)D  nagios3
>   0.2% (  1.9)D  gnome-terminal
>   0.7% (  6.4)   [Thermal event interrupts] <kernel IPI>
>
>
>
>

Re: Loopback performance from kernel 2.6.12 to 2.6.37

[Eric Dumazet]

Le mardi 09 novembre 2010 à 17:30 +1100, Andrew Hendry a écrit :
> most my slowdown was kmemleak left on.
> 
> After fixing its is still a lot slower than your dev system
> .
> # time dd if=/dev/zero bs=1M count=10000 | netcat  127.0.0.1 9999
> 10000+0 records in
> 10000+0 records out
> 10485760000 bytes (10 GB) copied, 25.8182 s, 406 MB/s
> 
> real	0m25.821s
> user	0m1.502s
> sys	0m33.463s
> 
> ------------------------------------------------------------------------------------------------------------------
>    PerfTop:     241 irqs/sec  kernel:56.8%  exact:  0.0% [1000Hz
> cycles],  (all, 8 CPUs)
> ------------------------------------------------------------------------------------------------------------------
> 
>              samples  pcnt function                    DSO
>              _______ _____ ___________________________
> ______________________________________
> 
>              1255.00  8.7% hpet_msi_next_event
> /lib/modules/2.6.37-rc1+/build/vmlinux
>              1081.00  7.5% copy_user_generic_string
> /lib/modules/2.6.37-rc1+/build/vmlinux
>               863.00  6.0% __ticket_spin_lock
> /lib/modules/2.6.37-rc1+/build/vmlinux
>               498.00  3.5% do_sys_poll
> /lib/modules/2.6.37-rc1+/build/vmlinux
>               455.00  3.2% system_call
> /lib/modules/2.6.37-rc1+/build/vmlinux
>               409.00  2.8% fget_light
> /lib/modules/2.6.37-rc1+/build/vmlinux
>               348.00  2.4% tcp_sendmsg
> /lib/modules/2.6.37-rc1+/build/vmlinux
>               269.00  1.9% fsnotify
> /lib/modules/2.6.37-rc1+/build/vmlinux
>               258.00  1.8% _raw_spin_unlock_irqrestore
> /lib/modules/2.6.37-rc1+/build/vmlinux
>               223.00  1.6% _raw_spin_lock_irqsave
> /lib/modules/2.6.37-rc1+/build/vmlinux
>               203.00  1.4% __clear_user
> /lib/modules/2.6.37-rc1+/build/vmlinux
>               184.00  1.3% tcp_poll
> /lib/modules/2.6.37-rc1+/build/vmlinux
>               178.00  1.2% vfs_write
> /lib/modules/2.6.37-rc1+/build/vmlinux
>               165.00  1.1% tcp_recvmsg
> /lib/modules/2.6.37-rc1+/build/vmlinux
>               152.00  1.1% pipe_read
> /lib/modules/2.6.37-rc1+/build/vmlinux
>               149.00  1.0% schedule
> /lib/modules/2.6.37-rc1+/build/vmlinux
>               135.00  0.9% rw_verify_area
> /lib/modules/2.6.37-rc1+/build/vmlinux
>               135.00  0.9% __pollwait
> /lib/modules/2.6.37-rc1+/build/vmlinux
>               130.00  0.9% __write
> /lib/libc-2.12.1.so
>               127.00  0.9% __ticket_spin_unlock
> /lib/modules/2.6.37-rc1+/build/vmlinux
>               126.00  0.9% __poll
> /lib/libc-2.12.1.so
> 
> 


Hmm, your clock source is HPET, that might explain the problem on a
scheduler intensive workload.

My HP dev machine
# grep . /sys/devices/system/clocksource/clocksource0/*
/sys/devices/system/clocksource/clocksource0/available_clocksource:tsc hpet acpi_pm 
/sys/devices/system/clocksource/clocksource0/current_clocksource:tsc

My laptop:
$ grep . /sys/devices/system/clocksource/clocksource0/*
/sys/devices/system/clocksource/clocksource0/available_clocksource:tsc hpet acpi_pm 
/sys/devices/system/clocksource/clocksource0/current_clocksource:tsc

Re: Loopback performance from kernel 2.6.12 to 2.6.37

[Eric Dumazet]

Le mardi 09 novembre 2010 à 07:38 +0100, Eric Dumazet a écrit :

> Hmm, your clock source is HPET, that might explain the problem on a
> scheduler intensive workload.
> 

And if a packet sniffer (dhclient for example) makes all packets being
timestamped, it also can explain a slowdown, even if there is no
scheduler artifacts.

cat /proc/net/packet

> My HP dev machine
> # grep . /sys/devices/system/clocksource/clocksource0/*
> /sys/devices/system/clocksource/clocksource0/available_clocksource:tsc hpet acpi_pm 
> /sys/devices/system/clocksource/clocksource0/current_clocksource:tsc
> 
> My laptop:
> $ grep . /sys/devices/system/clocksource/clocksource0/*
> /sys/devices/system/clocksource/clocksource0/available_clocksource:tsc hpet acpi_pm 
> /sys/devices/system/clocksource/clocksource0/current_clocksource:tsc
> 

Re: Loopback performance from kernel 2.6.12 to 2.6.37

[Jesper Dangaard Brouer]

On Mon, 2010-11-08 at 16:06 +0100, Eric Dumazet wrote:
...
> > > > > I noticed that the loopback performance has gotten quite bad:
> > > > > 
> > > > > http://www.phoronix.com/scan.php?page=article&item=linux_2612_2637&num=6
> >

> CC netdev, if you dont mind.

No problem :-)

> Their network test is basically :
> 
> netcat -l 9999 >/dev/null &
> time dd if=/dev/zero bs=1M count=10000 | netcat  127.0.0.1 9999

Should it not be:
 netcat -l -p 9999 >/dev/null &

When I run the commands "dd | netcat", netcat never finish/exits, I have
to press Ctrl-C to stop it.  What am I doing wrong? Any tricks?

"dd" reports 17.54 sec, and but the "time" measurement cannot be uses as
the netcat just hangs/waits for more data...

time dd if=/dev/zero bs=1M count=10000 | netcat 127.0.0.1 9999
10000+0 records in
10000+0 records out
10485760000 bytes (10 GB) copied, 17,5419 s, 598 MB/s

When I run the commands, I see 261682 context switches per sec...

This quick test were on a Core i7 920 using kernel
2.6.32-rc3-net-next-dev-mp2t.

-- 
Jesper Dangaard Brouer
ComX Networks A/S

Re: Loopback performance from kernel 2.6.12 to 2.6.37

[Eric Dumazet]

Le mardi 09 novembre 2010 à 14:59 +0100, Jesper Dangaard Brouer a
écrit :
> On Mon, 2010-11-08 at 16:06 +0100, Eric Dumazet wrote:
> ...
> > > > > > I noticed that the loopback performance has gotten quite bad:
> > > > > > 
> > > > > > http://www.phoronix.com/scan.php?page=article&item=linux_2612_2637&num=6
> > >
> 
> > CC netdev, if you dont mind.
> 
> No problem :-)
> 
> > Their network test is basically :
> > 
> > netcat -l 9999 >/dev/null &
> > time dd if=/dev/zero bs=1M count=10000 | netcat  127.0.0.1 9999
> 
> Should it not be:
>  netcat -l -p 9999 >/dev/null &
> 

It depends on netcat version. On yours, yes, you need the "-p"

> When I run the commands "dd | netcat", netcat never finish/exits, I have
> to press Ctrl-C to stop it.  What am I doing wrong? Any tricks?
> 
> "dd" reports 17.54 sec, and but the "time" measurement cannot be uses as
> the netcat just hangs/waits for more data...
> 

Your netcat version needs a "-c" switch

time dd if=/dev/zero bs=1M count=10000 | netcat -c 127.0.0.1 9999


> time dd if=/dev/zero bs=1M count=10000 | netcat 127.0.0.1 9999
> 10000+0 records in
> 10000+0 records out
> 10485760000 bytes (10 GB) copied, 17,5419 s, 598 MB/s
> 
> When I run the commands, I see 261682 context switches per sec...
> 
> This quick test were on a Core i7 920 using kernel
> 2.6.32-rc3-net-next-dev-mp2t.
> 

32 or 64bit kernel ?

Thanks !

Re: Loopback performance from kernel 2.6.12 to 2.6.37

[Jesper Dangaard Brouer]

On Tue, 2010-11-09 at 14:59 +0100, Jesper Dangaard Brouer wrote:
> On Mon, 2010-11-08 at 16:06 +0100, Eric Dumazet wrote:
> ...
> > > > > > I noticed that the loopback performance has gotten quite bad:
> > > > > > 
> > > > > > http://www.phoronix.com/scan.php?page=article&item=linux_2612_2637&num=6

> > Their network test is basically :
> > 
> > netcat -l 9999 >/dev/null &
> > time dd if=/dev/zero bs=1M count=10000 | netcat  127.0.0.1 9999
> 
> Should it not be:
>  netcat -l -p 9999 >/dev/null &
> 
> When I run the commands "dd | netcat", netcat never finish/exits, I have
> to press Ctrl-C to stop it.  What am I doing wrong? Any tricks?

To fix this I added "-q 0" to netcat.  Thus my working commands are:

 netcat -l -p 9999 >/dev/null &
 time dd if=/dev/zero bs=1M count=10000 | netcat -q0 127.0.0.1 9999

Running this on my "big" 10G testlab system, Dual Xeon 5550 2.67GHz,
kernel version 2.6.32-5-amd64 (which I usually don't use)
The results are 7.487 sec:

time dd if=/dev/zero bs=1M count=10000 | netcat -q0 127.0.0.1 9999
10000+0 records in
10000+0 records out
10485760000 bytes (10 GB) copied, 7,48562 s, 1,4 GB/s

real    0m7.487s
user    0m0.224s
sys     0m9.785s

Using vmstat I see approx 400000 context switches per sec.

Perf top says:
            samples  pcnt function                  DSO
             _______ _____ _________________________ ___________

             6442.00 16.3% copy_user_generic_string  [kernel]   
             2226.00  5.6% __clear_user              [kernel]   
              912.00  2.3% _spin_lock_irqsave        [kernel]   
              773.00  2.0% _spin_lock_bh             [kernel]   
              736.00  1.9% schedule                  [kernel]   
              582.00  1.5% ipt_do_table              [ip_tables]
              569.00  1.4% _spin_lock                [kernel]   
              505.00  1.3% get_page_from_freelist    [kernel]   
              451.00  1.1% _spin_unlock_irqrestore   [kernel]   
              434.00  1.1% do_select                 [kernel]   
              354.00  0.9% tcp_sendmsg               [kernel]   
              348.00  0.9% tick_nohz_stop_sched_tick [kernel]   
              347.00  0.9% tcp_transmit_skb          [kernel]   
              345.00  0.9% zero_fd_set               [kernel]   

Perf also complains about it cannot resolve netcat debug symbols.


-- 
Jesper Dangaard Brouer
ComX Networks A/S

Re: Loopback performance from kernel 2.6.12 to 2.6.37

[Eric Dumazet]

Le mardi 09 novembre 2010 à 15:16 +0100, Jesper Dangaard Brouer a
écrit :
> On Tue, 2010-11-09 at 14:59 +0100, Jesper Dangaard Brouer wrote:
> > On Mon, 2010-11-08 at 16:06 +0100, Eric Dumazet wrote:
> > ...
> > > > > > > I noticed that the loopback performance has gotten quite bad:
> > > > > > > 
> > > > > > > http://www.phoronix.com/scan.php?page=article&item=linux_2612_2637&num=6
> 
> > > Their network test is basically :
> > > 
> > > netcat -l 9999 >/dev/null &
> > > time dd if=/dev/zero bs=1M count=10000 | netcat  127.0.0.1 9999
> > 
> > Should it not be:
> >  netcat -l -p 9999 >/dev/null &
> > 
> > When I run the commands "dd | netcat", netcat never finish/exits, I have
> > to press Ctrl-C to stop it.  What am I doing wrong? Any tricks?
> 
> To fix this I added "-q 0" to netcat.  Thus my working commands are:
> 
>  netcat -l -p 9999 >/dev/null &
>  time dd if=/dev/zero bs=1M count=10000 | netcat -q0 127.0.0.1 9999
> 
> Running this on my "big" 10G testlab system, Dual Xeon 5550 2.67GHz,
> kernel version 2.6.32-5-amd64 (which I usually don't use)
> The results are 7.487 sec:
> 
> time dd if=/dev/zero bs=1M count=10000 | netcat -q0 127.0.0.1 9999
> 10000+0 records in
> 10000+0 records out
> 10485760000 bytes (10 GB) copied, 7,48562 s, 1,4 GB/s
> 
> real    0m7.487s
> user    0m0.224s
> sys     0m9.785s

So far, so good. These are the expected numbers. Now we have to
understand why corei7 gets 38 seconds instead of 8 :)

Re: Loopback performance from kernel 2.6.12 to 2.6.37

[Eric Dumazet]

Le mardi 09 novembre 2010 à 15:25 +0100, Eric Dumazet a écrit :

> So far, so good. These are the expected numbers. Now we have to
> understand why corei7 gets 38 seconds instead of 8 :)
> 
> 

My tests show a problem with backlog processing, and too big TCP
windows. (at least on loopback and wild senders)

Basically, with huge tcp windows we have now (default 4 Mbytes),
the reader process can have to process up to 4Mbytes of backlogged data
in __release_sock() before returning from its 'small' read(fd, buffer,
1024) done by netcat.

While it processes this backlog, it sends tcp ACKS, allowing sender to
send new frames that might be dropped because of sk_rcvqueues_full(), or
continue to fill receive queue up to the receiver window, feeding the
task in __release_sock() [loop]


This blows cpu caches completely [data is queued, and the dequeue is
done long after], and latency of a single read() can be very high. This
blocks the pipeline of user processing eventually.


<disgress>
I also understand why UDP latencies are so impacted. If we receive a
burst of frames on same socket, the user process reading first frame
might be forced to process the backlog before returning to userland.

Really we must zap lock_sock() from UDP input path.

commit 95766fff6b9a78d1 ([UDP]: Add memory accounting) was a big error.
</disgress>



On my server machine with 6Mbytes of L2 cache, you dont see the problem,
while on my laptop with 3Mbytes of L2 cache, you can see the problem.

I caught this because of new SNMP counter added in 2.6.34
(TCPBacklogDrop), that could easily take 1000 increments during the
test.


I built a test program, maybe easier to use than various netcat flavors
It also use two tasks only, thats better if you have a core 2 Duo like
me on my laptop ;)

To reproduce the problem, run it with option -l 4M

$ netstat -s|grep TCPBacklogDrop
    TCPBacklogDrop: 788
$ time ./loopback_transfert -l 1k;netstat -s|grep TCPBacklogDrop

real	0m14.013s
user	0m0.630s
sys	0m13.250s
    TCPBacklogDrop: 788
$ time ./loopback_transfert -l 128k;netstat -s|grep TCPBacklogDrop

real	0m7.447s
user	0m0.030s
sys	0m5.490s
    TCPBacklogDrop: 789
$ time ./loopback_transfert -l 1M;netstat -s|grep TCPBacklogDrop

real	0m11.206s
user	0m0.020s
sys	0m7.150s
    TCPBacklogDrop: 793
$ time ./loopback_transfert -l 4M;netstat -s|grep TCPBacklogDrop

real	0m10.347s
user	0m0.000s
sys	0m6.120s
    TCPBacklogDrop: 1510
$ time ./loopback_transfert -l 16k;netstat -s|grep TCPBacklogDrop

real	0m6.810s
user	0m0.040s
sys	0m6.670s
    TCPBacklogDrop: 1511


/*
 * Very simple program to test TCP loopback speed
 * This came from the phoronix benchmark using following :
 *
 * netcat -d -l 9999 >/dev/null &
 * time dd if=/dev/zero bs=1M count=10000 | netcat 127.0.0.1 9999
 *
 * Problem is the benchmark also use pipe subsystem, and three tasks,
 * while the following program uses only TCP subsystem and two tasks.
 * I still use small blocksize (netcat apparently use 1Kbyte blocks)
 *
 * Options :
 *            -l  blocksize   (in bytes, default : 1024)
 *            -s  socket SNDBUF/RCVBUF (default : system defaults (too big))
 */

#include <sys/types.h>
#include <sys/socket.h>
#include <netinet/in.h>
#include <netinet/tcp.h>
#include <string.h>
#include <unistd.h>
#include <stdio.h>
#include <stdlib.h>

long long amount_to_transfert = 10*1024*1024*1024LL; /* 10 Go */
unsigned int blocksize = 1024; /* to mimic netcat very pessimistic behavior */
unsigned int socket_bufsize = 0;

static void Server(int fdlisten)
{
	int newfd;
	struct sockaddr_in sockaddr;
	socklen_t len = sizeof(sockaddr);
	char *buffer;
	long total = 0;
	int ret;

	buffer = malloc(blocksize);
	newfd = accept(fdlisten, (struct sockaddr *)&sockaddr, &len);

	if (newfd == -1) {
		perror("accept");
		exit(1);
	}
	close(fdlisten);
	if (socket_bufsize)
		setsockopt(newfd, SOL_SOCKET, SO_RCVBUF, &socket_bufsize, 4);
	while (1) {
		ret = read(newfd, buffer, blocksize);
		if (ret <= 0) break;
		total += ret;
		}
	close(newfd);
	_exit(0);
}

static void usage(int code)
{
	exit(code);
}

static long scansize(char *str)
{
	char *end;
	long res = strtol(str, &end, 0);
	if (end) {
		if (*end == 'k') res <<= 10;
		if (*end == 'M') res <<= 20;
	}
	return res;
}

int main(int argc, char *argv[])
{
	int i;
	struct sockaddr_in sockaddr;
	socklen_t slen = sizeof(sockaddr);
	int fdlisten, fd;
	int port;
	char *buffer;
	long long total = 0;
	int ret = 0;

	while ((i = getopt(argc, argv, "l:s:")) != EOF) {
		if (i == 'l')
			blocksize = scansize(optarg);
		else if (i == 's')
			socket_bufsize = scansize(optarg);
		else usage(1);
	}
	buffer = calloc(blocksize, 1);
	fdlisten = socket(AF_INET, SOCK_STREAM, 0);
	if (fdlisten == -1) {
		perror("socket");
		return 1;
	}
	memset(&sockaddr, 0, sizeof(sockaddr));
	sockaddr.sin_family = AF_INET;
	sockaddr.sin_port = 0;
	sockaddr.sin_addr.s_addr = htonl(0x7f000001);
	if (bind(fdlisten, (struct sockaddr *)&sockaddr, sizeof(sockaddr))== -1) {
		perror("bind()");
		return 1;
	}
	if (listen(fdlisten, 10)== -1) {
		perror("listen");
		return 1;
	}
	getsockname(fdlisten, (struct sockaddr *)&sockaddr, &slen);
	port = ntohs(sockaddr.sin_port);

	if (fork() == 0)
		Server(fdlisten);

	close(fdlisten);
	fd = socket(AF_INET, SOCK_STREAM, 0);
	if (fd == -1) {
		perror("socket");
		return -1;
	}
	memset(&sockaddr, 0, sizeof(sockaddr));
	sockaddr.sin_family = AF_INET;
	sockaddr.sin_port = htons(port);
	sockaddr.sin_addr.s_addr = htonl(0x7f000001);
	if (socket_bufsize)
		setsockopt(fd, SOL_SOCKET, SO_SNDBUF, &socket_bufsize, 4);
	connect(fd, (struct sockaddr *)&sockaddr, sizeof(sockaddr));
	while (total < amount_to_transfert) {
		ret = write(fd, buffer, blocksize);
		if (ret <= 0) break;
		total += ret;
	}
	close(fd);
	return 0;
}

Re: Loopback performance from kernel 2.6.12 to 2.6.37

[Eric Dumazet]

Le jeudi 18 novembre 2010 à 14:52 +0100, Eric Dumazet a écrit :
> Le mardi 09 novembre 2010 à 15:25 +0100, Eric Dumazet a écrit :
> 
> > So far, so good. These are the expected numbers. Now we have to
> > understand why corei7 gets 38 seconds instead of 8 :)
> > 
> > 
> 
> My tests show a problem with backlog processing, and too big TCP
> windows. (at least on loopback and wild senders)
> 
> Basically, with huge tcp windows we have now (default 4 Mbytes),
> the reader process can have to process up to 4Mbytes of backlogged data
> in __release_sock() before returning from its 'small' read(fd, buffer,
> 1024) done by netcat.
> 
> While it processes this backlog, it sends tcp ACKS, allowing sender to
> send new frames that might be dropped because of sk_rcvqueues_full(), or
> continue to fill receive queue up to the receiver window, feeding the
> task in __release_sock() [loop]
> 
> 
> This blows cpu caches completely [data is queued, and the dequeue is
> done long after], and latency of a single read() can be very high. This
> blocks the pipeline of user processing eventually.
> 
> 
> <disgress>
> I also understand why UDP latencies are so impacted. If we receive a
> burst of frames on same socket, the user process reading first frame
> might be forced to process the backlog before returning to userland.
> 
> Really we must zap lock_sock() from UDP input path.
> 
> commit 95766fff6b9a78d1 ([UDP]: Add memory accounting) was a big error.
> </disgress>
> 
> 
> 
> On my server machine with 6Mbytes of L2 cache, you dont see the problem,
> while on my laptop with 3Mbytes of L2 cache, you can see the problem.
> 
> I caught this because of new SNMP counter added in 2.6.34
> (TCPBacklogDrop), that could easily take 1000 increments during the
> test.
> 
> 
> I built a test program, maybe easier to use than various netcat flavors
> It also use two tasks only, thats better if you have a core 2 Duo like
> me on my laptop ;)
> 
> To reproduce the problem, run it with option -l 4M
> 
> $ netstat -s|grep TCPBacklogDrop
>     TCPBacklogDrop: 788
> $ time ./loopback_transfert -l 1k;netstat -s|grep TCPBacklogDrop
> 
> real	0m14.013s
> user	0m0.630s
> sys	0m13.250s
>     TCPBacklogDrop: 788
> $ time ./loopback_transfert -l 128k;netstat -s|grep TCPBacklogDrop
> 
> real	0m7.447s
> user	0m0.030s
> sys	0m5.490s
>     TCPBacklogDrop: 789
> $ time ./loopback_transfert -l 1M;netstat -s|grep TCPBacklogDrop
> 
> real	0m11.206s
> user	0m0.020s
> sys	0m7.150s
>     TCPBacklogDrop: 793
> $ time ./loopback_transfert -l 4M;netstat -s|grep TCPBacklogDrop
> 
> real	0m10.347s
> user	0m0.000s
> sys	0m6.120s
>     TCPBacklogDrop: 1510
> $ time ./loopback_transfert -l 16k;netstat -s|grep TCPBacklogDrop
> 
> real	0m6.810s
> user	0m0.040s
> sys	0m6.670s
>     TCPBacklogDrop: 1511
> 

I forgot to include test results for my dev machine (server class
machine, 8 Mbytes of L2 cache) NUMA 
2 sockets : Intel(R) Xeon(R) CPU           E5540  @ 2.53GHz

# netstat -s|grep TCPBacklogDrop
    TCPBacklogDrop: 8891
# time ./loopback_transfert -l 16k;netstat -s|grep TCPBacklogDrop

real	0m7.033s
user	0m0.010s
sys	0m4.580s
    TCPBacklogDrop: 9239
# time ./loopback_transfert -l 1M;netstat -s|grep TCPBacklogDrop

real	0m5.408s
user	0m0.000s
sys	0m2.880s
    TCPBacklogDrop: 9243
# time ./loopback_transfert -l 4M;netstat -s|grep TCPBacklogDrop

real	0m2.965s
user	0m0.000s
sys	0m2.070s
    TCPBacklogDrop: 10485
# time ./loopback_transfert -l 6M;netstat -s|grep TCPBacklogDrop

real	0m7.711s
user	0m0.000s
sys	0m3.180s
    TCPBacklogDrop: 13537
# time ./loopback_transfert -l 8M;netstat -s|grep TCPBacklogDrop

real	0m11.497s
user	0m0.020s
sys	0m3.830s
    TCPBacklogDrop: 17108


As soon as our working set is larger than L2 cache, this is very slow.

for the -l 8M bench :

# Events: 7K cycles
#
# Overhead  Command      Shared Object                               Symbol
# ........  .......  .................  ...................................
#
    40.97%  loopback_transf  [kernel.kallsyms]  [k] copy_user_generic_string
    18.57%    :8968  [kernel.kallsyms]  [k] copy_user_generic_string
     3.54%    :8968  [kernel.kallsyms]  [k] get_page_from_freelist
     3.36%    :8968  [kernel.kallsyms]  [k] tcp_sendmsg
     1.17%    :8968  [kernel.kallsyms]  [k] put_page
     0.99%    :8968  [kernel.kallsyms]  [k] free_hot_cold_page
     0.99%    :8968  [kernel.kallsyms]  [k] __might_sleep
     0.88%    :8968  [kernel.kallsyms]  [k] __ticket_spin_lock
     0.81%  loopback_transf  [kernel.kallsyms]  [k] free_pcppages_bulk
     0.79%    :8968  [kernel.kallsyms]  [k] __alloc_pages_nodemask
     0.63%  loopback_transf  [kernel.kallsyms]  [k] put_page
     0.63%  loopback_transf  [kernel.kallsyms]  [k] __might_sleep
     0.63%  loopback_transf  [kernel.kallsyms]  [k] tcp_transmit_skb
     0.57%    :8968  [kernel.kallsyms]  [k] skb_release_data
     0.55%  loopback_transf  [kernel.kallsyms]  [k] free_hot_cold_page
     0.53%    :8968  [kernel.kallsyms]  [k] tcp_ack
     0.50%  loopback_transf  [kernel.kallsyms]  [k] __inet_lookup_established
     0.49%  loopback_transf  [kernel.kallsyms]  [k] skb_copy_datagram_iovec
     0.47%    :8968  [kernel.kallsyms]  [k] __rmqueue
     0.45%    :8968  [kernel.kallsyms]  [k] get_pageblock_flags_group
     0.41%    :8968  [kernel.kallsyms]  [k] zone_watermark_ok
     0.41%    :8968  [kernel.kallsyms]  [k] __inc_zone_state
     0.40%  loopback_transf  [kernel.kallsyms]  [k] skb_release_data
     0.39%    :8968  [kernel.kallsyms]  [k] tcp_transmit_skb

Re: Loopback performance from kernel 2.6.12 to 2.6.37

[David Miller]

From: Eric Dumazet <eric.dumazet@gmail.com>
Date: Thu, 18 Nov 2010 18:41:53 +0100

> Le jeudi 18 novembre 2010 à 14:52 +0100, Eric Dumazet a écrit :
>> Le mardi 09 novembre 2010 à 15:25 +0100, Eric Dumazet a écrit :
>> 
>> My tests show a problem with backlog processing, and too big TCP
>> windows. (at least on loopback and wild senders)
>> 
>> Basically, with huge tcp windows we have now (default 4 Mbytes),
>> the reader process can have to process up to 4Mbytes of backlogged data
>> in __release_sock() before returning from its 'small' read(fd, buffer,
>> 1024) done by netcat.
>> 
>> While it processes this backlog, it sends tcp ACKS, allowing sender to
>> send new frames that might be dropped because of sk_rcvqueues_full(), or
>> continue to fill receive queue up to the receiver window, feeding the
>> task in __release_sock() [loop]
>> 
>> 
>> This blows cpu caches completely [data is queued, and the dequeue is
>> done long after], and latency of a single read() can be very high. This
>> blocks the pipeline of user processing eventually.

Thanks for looking into this Eric.

We definitely need some kind of choke point so that TCP never
significantly exceeds the congestion window point at which throughput
stops increasing (and only latency does).

One idea is that when we integrate Lawrence Brakmo's TCP-NV congestion
control algorithm, we can try enabling it by default over loopback.

Loopback is kind of an interesting case of the problem scenerio
Lawrence is trying to solve.

Re: Loopback performance from kernel 2.6.12 to 2.6.37

[Jesper Dangaard Brouer]

On Tue, 2010-11-09 at 15:16 +0100, Jesper Dangaard Brouer wrote:
> On Tue, 2010-11-09 at 14:59 +0100, Jesper Dangaard Brouer wrote:
> > On Mon, 2010-11-08 at 16:06 +0100, Eric Dumazet wrote:
> > ...
> > > > > > > I noticed that the loopback performance has gotten quite bad:
> > > > > > > 
> > > > > > > http://www.phoronix.com/scan.php?page=article&item=linux_2612_2637&num=6
> 
> > > Their network test is basically :
> > > 
> > > netcat -l 9999 >/dev/null &
> > > time dd if=/dev/zero bs=1M count=10000 | netcat  127.0.0.1 9999
> > 
> > Should it not be:
> >  netcat -l -p 9999 >/dev/null &
> > 
> > When I run the commands "dd | netcat", netcat never finish/exits, I have
> > to press Ctrl-C to stop it.  What am I doing wrong? Any tricks?
> 
> To fix this I added "-q 0" to netcat.  Thus my working commands are:
> 
>  netcat -l -p 9999 >/dev/null &
>  time dd if=/dev/zero bs=1M count=10000 | netcat -q0 127.0.0.1 9999
> 
> Running this on my "big" 10G testlab system, Dual Xeon 5550 2.67GHz,
> kernel version 2.6.32-5-amd64 (which I usually don't use)
> The results are 7.487 sec

Using kernel 2.6.35.8-comx01+ (which is 35-stable with some minor
patches of my own) on the same type of hardware (our preprod server).
The result is 12 sec.

time dd if=/dev/zero bs=1M count=10000 | netcat -q0 127.0.0.1 9999
10000+0 records in
10000+0 records out
10485760000 bytes (10 GB) copied, 12,0805 s, 868 MB/s

real    0m12.082s
user    0m0.311s
sys     0m15.896s

BUT perf top reveals that its probably related to the function
'find_busiest_group' ... any kernel config hints how I get rid of that?


              samples  pcnt function                    DSO
             _______ _____ ___________________________ ______________

             4152.00 12.8% copy_user_generic_string    [kernel]      
             1802.00  5.6% find_busiest_group          [kernel]      
              852.00  2.6% __clear_user                [kernel]      
              836.00  2.6% _raw_spin_lock_bh           [kernel]      
              819.00  2.5% ipt_do_table                [ip_tables]   
              628.00  1.9% rebalance_domains           [kernel]      
              564.00  1.7% _raw_spin_lock              [kernel]      
              562.00  1.7% _raw_spin_lock_irqsave      [kernel]      
              522.00  1.6% schedule                    [kernel]      
              441.00  1.4% find_next_bit               [kernel]      
              413.00  1.3% _raw_spin_unlock_irqrestore [kernel]      
              394.00  1.2% tcp_sendmsg                 [kernel]      
              391.00  1.2% tcp_packet                  [nf_conntrack]
              368.00  1.1% do_select                   [kernel]      



> Using vmstat I see approx 400000 context switches per sec.
>
Previous:
> Perf top says:
>             samples  pcnt function                  DSO
>              _______ _____ _________________________ ___________
> 
>              6442.00 16.3% copy_user_generic_string  [kernel]   
>              2226.00  5.6% __clear_user              [kernel]   
>               912.00  2.3% _spin_lock_irqsave        [kernel]   
>               773.00  2.0% _spin_lock_bh             [kernel]   
>               736.00  1.9% schedule                  [kernel]   
>               582.00  1.5% ipt_do_table              [ip_tables]
>               569.00  1.4% _spin_lock                [kernel]   
>               505.00  1.3% get_page_from_freelist    [kernel]   
>               451.00  1.1% _spin_unlock_irqrestore   [kernel]   
>               434.00  1.1% do_select                 [kernel]   
>               354.00  0.9% tcp_sendmsg               [kernel]   
>               348.00  0.9% tick_nohz_stop_sched_tick [kernel]   
>               347.00  0.9% tcp_transmit_skb          [kernel]   
>               345.00  0.9% zero_fd_set               [kernel]   


-- 
Jesper Dangaard Brouer
ComX Networks A/S

Re: Loopback performance from kernel 2.6.12 to 2.6.37

[Jesper Dangaard Brouer]

On Tue, 2010-11-09 at 15:38 +0100, Jesper Dangaard Brouer wrote:
> On Tue, 2010-11-09 at 15:16 +0100, Jesper Dangaard Brouer wrote:
> > On Tue, 2010-11-09 at 14:59 +0100, Jesper Dangaard Brouer wrote:
> > > On Mon, 2010-11-08 at 16:06 +0100, Eric Dumazet wrote:
> > > ...
> > 
> > To fix this I added "-q 0" to netcat.  Thus my working commands are:
> > 
> >  netcat -l -p 9999 >/dev/null &
> >  time dd if=/dev/zero bs=1M count=10000 | netcat -q0 127.0.0.1 9999
> > 
> > Running this on my "big" 10G testlab system, Dual Xeon 5550 2.67GHz,
> > kernel version 2.6.32-5-amd64 (which I usually don't use)
> > The results are 7.487 sec
> 
> Using kernel 2.6.35.8-comx01+ (which is 35-stable with some minor
> patches of my own) on the same type of hardware (our preprod server).
> The result is 12 sec.
> 
> time dd if=/dev/zero bs=1M count=10000 | netcat -q0 127.0.0.1 9999
> 10000+0 records in
> 10000+0 records out
> 10485760000 bytes (10 GB) copied, 12,0805 s, 868 MB/s
> 
> real    0m12.082s
> user    0m0.311s
> sys     0m15.896s

On the same system I can better performance IF I pin the processes on
different CPUs. BUT the trick here is I choose CPUs with different "core
id", thus I avoid the HT CPUs in the system (hint look in /proc/cpuinfo
for choosing the CPUs).

Commands:
 taskset 16 netcat -lv -p 9999 >/dev/null &
 time taskset 1 dd if=/dev/zero bs=1M count=10000 | taskset 4 netcat -q0 127.0.0.1 9999

Result:
 10485760000 bytes (10 GB) copied, 8,74021 s, 1,2 GB/s
 real    0m8.742s
 user    0m0.208s
 sys     0m11.426s

So, perhaps the Core i7 has a problem with the HT CPUs with this
workload?

Forcing dd and netcat on the same HT CPU gives a result of approx 18
sec!

Commands:
 taskset 16 netcat -lv -p 9999 >/dev/null
 time taskset 1 dd if=/dev/zero bs=1M count=10000 | taskset 2 netcat -q0 127.0.0.1 9999

Result:
 10485760000 bytes (10 GB) copied, 18,6575 s, 562 MB/s
 real    0m18.659s
 user    0m0.341s
 sys     0m18.969s


> BUT perf top reveals that its probably related to the function
> 'find_busiest_group' ... any kernel config hints how I get rid of that?

The 'find_busiest_group' seems to be an artifact of "perf top", if I use
"perf record" then the 'find_busiest_group' function disappears.  Which
is kind of strange, as 'find_busiest_group' seem the be related to
sched_fair.c.

perf --version
perf version 2.6.35.7.1.g60d9c

-- 
Med venlig hilsen / Best regards
  Jesper Brouer
  ComX Networks A/S
  Linux Network Kernel Developer
  Cand. Scient Datalog / MSc.CS
  Author of http://adsl-optimizer.dk
  LinkedIn: http://www.linkedin.com/in/brouer

Re: Loopback performance from kernel 2.6.12 to 2.6.37

[Arnaldo Carvalho de Melo]

Em Wed, Nov 10, 2010 at 12:24:16PM +0100, Jesper Dangaard Brouer escreveu:
> > BUT perf top reveals that its probably related to the function
> > 'find_busiest_group' ... any kernel config hints how I get rid of that?
> 
> The 'find_busiest_group' seems to be an artifact of "perf top", if I use
> "perf record" then the 'find_busiest_group' function disappears.  Which
> is kind of strange, as 'find_busiest_group' seem the be related to
> sched_fair.c.
> 
> perf --version
> perf version 2.6.35.7.1.g60d9c

perf top does sytemwide sampling, while when you use 'perf record
./workload' its not systemwide.

Take a look at 'perf top --help' to see how to limit this to an existing
pid, tid, cpu list, etc.

- Arnaldo