AES-CTR MT slower than vanilla

[allanjude]

In my tests, the MT implementation of AES-CTR appears to be significantly slower than the implementation used in the current version of OpenSSH.

This is on a high end server:
Intel(R) Xeon(R) CPU E5-1650 v3, 6 cores @ 3.50GHz + HT (12 threads)

In a job that sends data from the server, to a receiving client:
ssh -c aes128-ctr -m umac-64-etm@openssh.com user@host dd if=/dev/zero bs=128k | dd of=/dev/null bs=128k

MT-AES-CTR on both sides:
2000846848 bytes transferred in 10.001863 secs (200047414 bytes/sec)

MT-AES-CTR on client side only:
2884976640 bytes transferred in 10.050173 secs (287057417 bytes/sec)

MT-AES-CTR on server side only:
2868396032 bytes transferred in 10.002210 secs (286776221 bytes/sec)

MT-AES-CTR disabled on both sides:
5973835776 bytes transferred in 10.001882 secs (597271167 bytes/sec)

I tried recompiling with CIPHER_THREADS increased from 2 to 4. It makes it use more CPU, but throughput only goes up fractionally to around 300 MB/s.

[vapier]

what version are you testing against exactly ?

[allanjude]

All of the tests were done again:
OpenSSH_7.3p1-hpn14v12, OpenSSL 1.0.2j-freebsd 26 Sep 2016

just with or without -odisablemtaes=yes on the client/server side

but same results my git checkout on the client side, to an entirely unpatched server:
OpenSSH_7.2p2, OpenSSL 1.0.2j-freebsd 26 Sep 2016

with -odisablemtaes=no
2874408960 bytes transferred in 10.001432 secs (287399754 bytes/sec)

with -odisablemtaes=yes:
5847531520 bytes transferred in 10.034207 secs (582759730 bytes/sec)

[rapier1]

Hi, sorry I've been out of communication for a while. It's been a weird few months. Anyway, I'm running some tests on this now. I was hoping you could send me information about your hardware setup and your network path. Thanks, Chris

…

On 1/8/17 12:27 PM, Allan Jude wrote: All of the tests were done again: OpenSSH_7.3p1-hpn14v12, OpenSSL 1.0.2j-freebsd 26 Sep 2016 just with or without -odisablemtaes=yes on the client/server side but same results my git checkout on the client side, to an entirely unpatched server: OpenSSH_7.2p2, OpenSSL 1.0.2j-freebsd 26 Sep 2016 with -odisablemtaes=no 2874408960 bytes transferred in 10.001432 secs (287399754 bytes/sec) with -odisablemtaes=yes: 5847531520 bytes transferred in 10.034207 secs (582759730 bytes/sec) — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub <#13 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/ABS_ePZ1K-39BcwL2FHhQzFBxGRNpLBZks5rQRyXgaJpZM4LdoDW>.

[allanjude]

In this case it is a very high end system, Intel(R) Xeon(R) CPU E5-1650 v3, 6 cores @ 3.50GHz + HT (compared to an E5-2650 this machine has a much higher CPU frequency)

These tests can be done just over localhost to eliminate any network effects. But my tests were done over Chelsio T580 40gbps NICs connected back-to-back between a pair of these machines (made available to me by the FreeBSD Foundation for testing)

[rapier1]

I'm doing some back to back testing as well (quad core xeon with 10GB NICS). At this point I'm not seeing the same effects that you are but that might be due to differences in how we are conducting the tests. Could you let me know how you are conducting the tests? E.g. Are you piping urandom through ssh to /dev/null? How are you getting the test results? etc. As a note: on a high end system I wouldn't expect there to be much difference between aes-ctr and aes-ctr-mt. The mt cipher is really only going to show a big difference when the process is processor bound. However, I really wouldn't expect it to be slower so this is a mystery. Thanks!

…

On 1/9/17 12:05 PM, Allan Jude wrote: In this case it is a very high end system, Intel(R) Xeon(R) CPU E5-1650 v3, 6 cores @ 3.50GHz + HT (compared to an E5-2650 this machine has a much higher CPU frequency) These tests can be done just over localhost to eliminate any network effects. But my tests were done over Chelsio T580 40gbps NICs connected back-to-back between a pair of these machines (made available to me by the FreeBSD Foundation for testing) — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#13 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/ABS_eBnM91q6WUVCvpKUdtwH9rJhvo78ks5rQmi8gaJpZM4LdoDW>.

[allanjude]

I did not use dev/random because it would likely be the performance bottleneck.

I just ran:
ssh -c aes128-ctr -m umac-64-etm@openssh.com user@localhost dd if=/dev/zero bs=128k | dd of=/dev/null bs=128k

varied by adding '-odisablemtaes=yes' on the client, server, and both.

I have been using timelimit(1) to make the measurements 30 seconds.:
timelimit -q -t 30

I see the threading working, it just isn't faster than without the multi-threading:
PID USERNAME THR PRI NICE SIZE RES STATE C TIME WCPU COMMAND
84592 root 5 85 0 24720K 6080K CPU1 1 0:49 242.77% ssh
84595 test 5 85 0 27404K 6168K CPU7 7 0:49 240.59% sshd

I also tried underclocking my system to see what impact a slower clock speed (1200mhz vs 3500mhz) had:

(MT: C: ON, S: ON):
3500mhz: 8771600384 bytes transferred in 30.001552 secs (292371553 bytes/sec)
1200mhz: 3004858368 bytes transferred in 30.002547 secs (100153442 bytes/sec)

(MT: C: OFF, S: ON):
3500mhz: 8785854464 bytes transferred in 30.001381 secs (292848338 bytes/sec)
1200mhz: 2982739968 bytes transferred in 30.002141 secs (99417571 bytes/sec)

(MT: C: ON, S: OFF):
3500mhz: 8786575360 bytes transferred in 30.002099 secs (292865359 bytes/sec)
1200mhz: 3018129408 bytes transferred in 30.090607 secs (100301381 bytes/sec)

(MT: C: OFF, S: OFF):
3500mhz: 20275757056 bytes transferred in 30.030299 secs (675176654 bytes/sec)
1200mhz: 6847234048 bytes transferred in 30.078079 secs (227648646 bytes/sec)

[rapier1]

I'm looking into replicating this right now. However, in the meantime could you do me a favor and make sure compression is disabled? Being that we're dealing with /dev/zero compression could have a big impact. If compression doesn't make a difference I'm concerned that we may be having some issues with the way that the threads are interacting with core caches. It could be that the cache hits are actually degrading performance on some architectures.

…

On 1/10/17 1:17 AM, Allan Jude wrote: ssh -c aes128-ctr -m ***@***.*** ***@***.***> ***@***.*** dd if=/dev/zero bs=128k | dd of=/dev/null bs=128k

[rapier1]

Here are the results I received: 7.3 to 7.3 2805006336 bytes (2.8 GB) copied, 30.0009 s, 93.5 MB/s 3783049216 bytes (3.8 GB) copied, 30 s, 126 MB/s 3940433920 bytes (3.9 GB) copied, 30.0004 s, 131 MB/s 3729244160 bytes (3.7 GB) copied, 30.0007 s, 124 MB/s 3794944000 bytes (3.8 GB) copied, 30.0003 s, 126 MB/s 7.3 to 7.3 HPN 3238035456 bytes (3.2 GB) copied, 30.0005 s, 108 MB/s 2894823424 bytes (2.9 GB) copied, 30.0011 s, 96.5 MB/s 3244261376 bytes (3.2 GB) copied, 30.0002 s, 108 MB/s 3251404800 bytes (3.3 GB) copied, 30.0013 s, 108 MB/s 3229319168 bytes (3.2 GB) copied, 30.0006 s, 108 MB/s 7.3 to 7.3 HPN (mt off) 3830857728 bytes (3.8 GB) copied, 30.0005 s, 128 MB/s 4178116608 bytes (4.2 GB) copied, 30.0005 s, 139 MB/s 3771613184 bytes (3.8 GB) copied, 30.0004 s, 126 MB/s 3769401344 bytes (3.8 GB) copied, 30.0011 s, 126 MB/s 3809837056 bytes (3.8 GB) copied, 30.0005 s, 127 MB/s 7.3 HPN to 7.3 HPN 3154821120 bytes (3.2 GB) copied, 30.001 s, 105 MB/s 3279585280 bytes (3.3 GB) copied, 30.0011 s, 109 MB/s 3257384960 bytes (3.3 GB) copied, 30.0007 s, 109 MB/s 3263643648 bytes (3.3 GB) copied, 30.0007 s, 109 MB/s 3252486144 bytes (3.3 GB) copied, 30.0007 s, 108 MB/s 7.3 HPN to 7.3 HPN (mt off) 3712434176 bytes (3.7 GB) copied, 30.0007 s, 124 MB/s 3772366848 bytes (3.8 GB) copied, 30.0005 s, 126 MB/s 3805855744 bytes (3.8 GB) copied, 30.0006 s, 127 MB/s 3739009024 bytes (3.7 GB) copied, 30.0005 s, 125 MB/s 3811459072 bytes (3.8 GB) copied, 30.0008 s, 127 MB/s 7.3 HPN (mt off) to 7.3 HPN (mt off) 3811639296 bytes (3.8 GB) copied, 30.0005 s, 127 MB/s 3619831808 bytes (3.6 GB) copied, 30.0006 s, 121 MB/s 3954081792 bytes (4.0 GB) copied, 30.0006 s, 132 MB/s 3844145152 bytes (3.8 GB) copied, 30.0005 s, 128 MB/s 3821371392 bytes (3.8 GB) copied, 30.0005 s, 127 MB/s So it looks like you are right when the server is using the aes-ctr-mt cipher. I need to rerun some of theses tests with the remote server sending to the local client. I know that our initial tests showed a definite improvement over vanilla aes-ctr so I need to determine why this is happening now and if it makes sense to continue supporting the threaded cipher. There could be a number of reasons for this and I'm not sure which avenue to explore at the moment. I'd also like to try this out on non Xeon architectures to see if there is something particular to it that might be impacting this. For example, if it's a dual CPU system the inter-communications between the CPUs would definitely cause a problem if the threads are split over the CPUs instead of being bound to a single one. More investigation on the way.

…

On 1/10/17 1:17 AM, Allan Jude wrote: I did not use dev/random because it would likely be the performance bottleneck. I just ran: ssh -c aes128-ctr -m ***@***.*** ***@***.***> ***@***.*** dd if=/dev/zero bs=128k | dd of=/dev/null bs=128k varied by adding '-odisablemtaes=yes' on the client, server, and both. I have been using timelimit(1) to make the measurements 30 seconds.: timelimit -q -t 30 I see the threading working, it just isn't faster than without the multi-threading: PID USERNAME THR PRI NICE SIZE RES STATE C TIME WCPU COMMAND 84592 root 5 85 0 24720K 6080K CPU1 1 0:49 242.77% ssh 84595 test 5 85 0 27404K 6168K CPU7 7 0:49 240.59% sshd I also tried underclocking my system to see what impact a slower clock speed (1200mhz vs 3500mhz) had: (MT: C: ON, S: ON): 3500mhz: 8771600384 bytes transferred in 30.001552 secs (292371553 bytes/sec) 1200mhz: 3004858368 bytes transferred in 30.002547 secs (100153442 bytes/sec) (MT: C: OFF, S: ON): 3500mhz: 8785854464 bytes transferred in 30.001381 secs (292848338 bytes/sec) 1200mhz: 2982739968 bytes transferred in 30.002141 secs (99417571 bytes/sec) (MT: C: ON, S: OFF): 3500mhz: 8786575360 bytes transferred in 30.002099 secs (292865359 bytes/sec) 1200mhz: 3018129408 bytes transferred in 30.090607 secs (100301381 bytes/sec) (MT: C: OFF, S: OFF): 3500mhz: 20275757056 bytes transferred in 30.030299 secs (675176654 bytes/sec) 1200mhz: 6847234048 bytes transferred in 30.078079 secs (227648646 bytes/sec) — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#13 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/ABS_eLPbpKK4bbOycGQgKQbTpJIe9qVOks5rQyKJgaJpZM4LdoDW>.

[allanjude]

My test system is a single socket Xeon E5-1650, but yes, I am not sure where along the way the threading seemed to stop helping.

If it could be made to work again, I think it would be very helpful, as many machines has 8-32 cores now, and are constrained by the performance of one core when trying to transfer data at 10 and 40 gbps.

[rapier1]

So I finally found out what is going on. Several years ago the AES cypher system was updated to AES New Instructions (AES-NI) and it looks like they significantly improved the single stream efficiency. Since AES-CTR-MT predates that code it doesn't include the NI enhancements. The original author of the AES-CTR-MT code is taking a look at it now and we may be able to incorporate NI. I'll keep people informed.

As a note: It looks like AES-NI is dependent on a version of OpenSSL > 1.0 and requires that the AES-NI instruction set be present in the CPU itself (so Intel Westmere cores and later). As such, the performance bump is arch dependent.

[vapier]

hmm, can we detect the presence of AES-NI dynamically ? i know cpuid can tell you about AES in general ...

[rapier1]

I'd assume there is a method for it. I'll need to look at the current AES implementation to see how they handle it. My gut feeling is that I/we should be able to update the AES-CTR-MT code to incorporate AES-NI once I figure that out.

[rapier1]

As an update - I contacted the guy that did the original work on the AES-CTR-MT cipher a month or so ago. I just pinged him again to see if he had any thoughts on this.