Thread: SSL encryption makes bytea transfer slow
We selected a 30MB bytea with psql connected with "-h localhost" and found that it makes a huge difference whether we have SSL encryption on or off. Without SSL the SELECT finished in about a second, with SSL it took over 23 seconds (measured with \timing in psql). During that time, the CPU is 100% busy. All data are cached in memory. Is this difference as expected? Yours, Laurenz Albe
On 28.10.2011 14:02, Albe Laurenz wrote: > We selected a 30MB bytea with psql connected with > "-h localhost" and found that it makes a huge > difference whether we have SSL encryption on or off. > > Without SSL the SELECT finished in about a second, > with SSL it took over 23 seconds (measured with > \timing in psql). > During that time, the CPU is 100% busy. > All data are cached in memory. > > Is this difference as expected? I tried to reproduce that, but only saw about 4x difference in the timing, not 23x. $ PGSSLMODE=disable ~/pgsql.master/bin/psql -h localhost postgres psql (9.2devel) Type "help" for help. postgres=# \o foo postgres=# \timing Timing is on. postgres=# SELECT repeat(xx,65536)::bytea FROM (SELECT string_agg(lpad(to_hex(x),2, '0' ),'') AS xx FROM generate_series(0,255) x) AS xx; Time: 460,782 ms $ PGSSLMODE=require ~/pgsql.master/bin/psql -h localhost postgres psql (9.2devel) SSL connection (cipher: DHE-RSA-AES256-SHA, bits: 256) Type "help" for help. postgres=# \o foo postgres=# \timing Timing is on. postgres=# SELECT repeat(xx,65536)::bytea FROM (SELECT string_agg(lpad(to_hex(x),2, '0' ),'') AS xx FROM generate_series(0,255) x) AS xx; Time: 1874,276 ms oprofile suggests that all that overhead is coming from compression. Apparently SSL does compression automatically. Oprofile report of the above test case with SSL enabled: samples % image name symbol name 28177 74.4753 libz.so.1.2.3.4 /usr/lib/libz.so.1.2.3.4 1814 4.7946 postgres byteain 1459 3.8563 libc-2.13.so __memcpy_ssse3_back 1437 3.7982 libcrypto.so.0.9.8 /usr/lib/libcrypto.so.0.9.8 896 2.3682 postgres hex_encode 304 0.8035 vmlinux-3.0.0-1-amd64 clear_page_c 271 0.7163 libc-2.13.so __strlen_sse42 222 0.5868 libssl.so.0.9.8 /usr/lib/libssl.so.0.9.8 And without: samples % image name symbol name 1601 27.4144 postgres byteain 865 14.8116 postgres hex_encode 835 14.2979 libc-2.13.so __memcpy_ssse3_back 290 4.9658 vmlinux-3.0.0-1-amd64 clear_page_c 280 4.7945 libc-2.13.so __strlen_sse42 184 3.1507 vmlinux-3.0.0-1-amd64 page_fault 174 2.9795 vmlinux-3.0.0-1-amd64 put_mems_allowed Maybe your data is very expensive to compress for some reason? -- Heikki Linnakangas EnterpriseDB http://www.enterprisedb.com
Heikki Linnakangas wrote: >> We selected a 30MB bytea with psql connected with >> "-h localhost" and found that it makes a huge >> difference whether we have SSL encryption on or off. >> >> Without SSL the SELECT finished in about a second, >> with SSL it took over 23 seconds (measured with >> \timing in psql). >> During that time, the CPU is 100% busy. >> All data are cached in memory. >> >> Is this difference as expected? Thanks for looking at that. > I tried to reproduce that, but only saw about 4x difference in the > timing, not 23x. I tried more tests on an idle server, and the factor I observe here is 3 or 4 as you say. The original measurements were taken on a server under load. > oprofile suggests that all that overhead is coming from compression. > Apparently SSL does compression automatically. Oprofile report of the > above test case with SSL enabled: > > samples % image name symbol name > 28177 74.4753 libz.so.1.2.3.4 /usr/lib/libz.so.1.2.3.4 > 1814 4.7946 postgres byteain > 1459 3.8563 libc-2.13.so __memcpy_ssse3_back > 1437 3.7982 libcrypto.so.0.9.8 /usr/lib/libcrypto.so.0.9.8 > 896 2.3682 postgres hex_encode > 304 0.8035 vmlinux-3.0.0-1-amd64 clear_page_c > 271 0.7163 libc-2.13.so __strlen_sse42 > 222 0.5868 libssl.so.0.9.8 /usr/lib/libssl.so.0.9.8 > > And without: > > samples % image name symbol name > 1601 27.4144 postgres byteain > 865 14.8116 postgres hex_encode > 835 14.2979 libc-2.13.so __memcpy_ssse3_back > 290 4.9658 vmlinux-3.0.0-1-amd64 clear_page_c > 280 4.7945 libc-2.13.so __strlen_sse42 > 184 3.1507 vmlinux-3.0.0-1-amd64 page_fault > 174 2.9795 vmlinux-3.0.0-1-amd64 put_mems_allowed > > > Maybe your data is very expensive to compress for some reason? Funny, I cannot see any calls to libz. On my system (RHEL 3, PostgreSQL 8.4.8, openssl 0.9.7a) the oprofile reports of the server process look like this: With SSL: samples % symbol name image name 5326 77.6611 (no symbol) /lib/libcrypto.so.0.9.7a 755 11.009 byteaout /magwien/postgres-8.4.8/bin/postgres 378 5.51181 __GI_memcpy /lib/tls/libc-2.3.2.so 220 3.20793 printtup /magwien/postgres-8.4.8/bin/postgres Without SSL: samples % symbol name image name 765 55.8394 byteaout /magwien/postgres-8.4.8/bin/postgres 293 21.3869 __GI_memcpy /lib/tls/libc-2.3.2.so 220 16.0584 printtup /magwien/postgres-8.4.8/bin/postgres Could that still be compression? The test I am running is: $ psql "host=localhost sslmode=... dbname=test" test=> \o /dev/null test=> select val from images where id=2; test=> \q Yours, Laurenz Albe
On Mon, Oct 31, 2011 at 10:34 AM, Albe Laurenz <laurenz.albe@wien.gv.at> wrote: > Heikki Linnakangas wrote: >>> We selected a 30MB bytea with psql connected with >>> "-h localhost" and found that it makes a huge >>> difference whether we have SSL encryption on or off. >>> >>> Without SSL the SELECT finished in about a second, >>> with SSL it took over 23 seconds (measured with >>> \timing in psql). >>> During that time, the CPU is 100% busy. >>> All data are cached in memory. >>> >>> Is this difference as expected? > > Thanks for looking at that. > >> I tried to reproduce that, but only saw about 4x difference in the >> timing, not 23x. > > I tried more tests on an idle server, and the factor I observe here is > 3 or 4 as you say. The original measurements were taken on a server > under load. > >> oprofile suggests that all that overhead is coming from compression. >> Apparently SSL does compression automatically. Oprofile report of the >> above test case with SSL enabled: >> >> samples % image name symbol name >> 28177 74.4753 libz.so.1.2.3.4 /usr/lib/libz.so.1.2.3.4 >> 1814 4.7946 postgres byteain >> 1459 3.8563 libc-2.13.so __memcpy_ssse3_back >> 1437 3.7982 libcrypto.so.0.9.8 /usr/lib/libcrypto.so.0.9.8 >> 896 2.3682 postgres hex_encode >> 304 0.8035 vmlinux-3.0.0-1-amd64 clear_page_c >> 271 0.7163 libc-2.13.so __strlen_sse42 >> 222 0.5868 libssl.so.0.9.8 /usr/lib/libssl.so.0.9.8 >> >> And without: >> >> samples % image name symbol name >> 1601 27.4144 postgres byteain >> 865 14.8116 postgres hex_encode >> 835 14.2979 libc-2.13.so __memcpy_ssse3_back >> 290 4.9658 vmlinux-3.0.0-1-amd64 clear_page_c >> 280 4.7945 libc-2.13.so __strlen_sse42 >> 184 3.1507 vmlinux-3.0.0-1-amd64 page_fault >> 174 2.9795 vmlinux-3.0.0-1-amd64 put_mems_allowed >> >> >> Maybe your data is very expensive to compress for some reason? > > Funny, I cannot see any calls to libz. On my system (RHEL 3, PostgreSQL > 8.4.8, > openssl 0.9.7a) the oprofile reports of the server process look like > this: > > With SSL: > > samples % symbol name image name > 5326 77.6611 (no symbol) /lib/libcrypto.so.0.9.7a that's a pretty ancient crypto you got there...it may not compress by default. Heikki's test data will compress super well which would totally skew performance testing to libz since the amount of data actually encrypted will be fairly tiny. real world high entropy cases often show crypto as the worse offender in my experience. merlin
Merlin Moncure wrote: >>>> We selected a 30MB bytea with psql connected with >>>> "-h localhost" and found that it makes a huge >>>> difference whether we have SSL encryption on or off. >>>> >>>> Without SSL the SELECT finished in about a second, >>>> with SSL it took over 23 seconds (measured with >>>> \timing in psql). >>>> During that time, the CPU is 100% busy. >>>> All data are cached in memory. >>>> >>>> Is this difference as expected? >>> I tried to reproduce that, but only saw about 4x difference in the >>> timing, not 23x. >>> oprofile suggests that all that overhead is coming from compression. >>> Apparently SSL does compression automatically. Oprofile report of the >>> above test case with SSL enabled: [...] >> Funny, I cannot see any calls to libz. On my system (RHEL 3, PostgreSQL >> 8.4.8, openssl 0.9.7a) the oprofile reports of the server process look >> like this: >> samples % symbol name image name >> 5326 77.6611 (no symbol) /lib/libcrypto.so.0.9.7a > that's a pretty ancient crypto you got there...it may not compress by > default. Heikki's test data will compress super well which would > totally skew performance testing to libz since the amount of data > actually encrypted will be fairly tiny. real world high entropy cases > often show crypto as the worse offender in my experience. I experimented some more on a recent system (RHEL6, OpenSSL 1.0.0-fips), and it is as you say. Disabling OpenSSL compression in the source (which is possible since OpenSSL 1.0.0) does not give me any performance improvement. Seems you pretty much have to live with at most 1/4 of the performance if you want to SELECT large images using SSL. Yours, Laurenz Albe
On Thu, Nov 03, 2011 at 03:48:11PM +0100, Albe Laurenz wrote: > > I experimented some more on a recent system (RHEL6, OpenSSL 1.0.0-fips), > and it is as you say. Disabling OpenSSL compression in the source (which > is possible since OpenSSL 1.0.0) does not give me any performance > improvement. > > Seems you pretty much have to live with at most 1/4 of the performance > if you want to SELECT large images using SSL. > > Yours, > Laurenz Albe > Have you tried different ciphers? RC4 is much lighter weight CPU-wise then the typically negotiated cipher. AES128 is also not bad if you have the newer Intel chips with the hardware encryption support. Just another thing to check. Regards, Ken
On Fri, Oct 28, 2011 at 14:02, Albe Laurenz <laurenz.albe@wien.gv.at> wrote: > Without SSL the SELECT finished in about a second, > with SSL it took over 23 seconds (measured with > \timing in psql). When you query with psql, it requests columns in text format. Since bytea hex-encodes its value if output is text, this means it's transmitting 60 MB for a 30 MB bytea value. If you could make sure that your app is requesting binary output, then you could cut 50% off this time. As others mentioned, most of the overhead is in SSL compression (not encryption), which can be disabled, but is not very easy to do. But 23 seconds for 60 MB is still *very* slow, so something else could be going wrong. What kind of CPU is this? On Thu, Nov 3, 2011 at 16:48, Albe Laurenz <laurenz.albe@wien.gv.at> wrote: > Disabling OpenSSL compression in the source (which > is possible since OpenSSL 1.0.0) does not give me any performance > improvement. If it doesn't give you any performance improvement then you haven't disabled compression. Modern CPUs can easily saturate 1 GbitE with AES256-encrypted connections. Compression is usually the bottleneck, at 20-30 MB/s. Regards, Marti
Marti Raudsepp wrote: >> Disabling OpenSSL compression in the source (which >> is possible since OpenSSL 1.0.0) does not give me any performance >> improvement. > > If it doesn't give you any performance improvement then you haven't > disabled compression. Modern CPUs can easily saturate 1 GbitE with > AES256-encrypted connections. Compression is usually the bottleneck, > at 20-30 MB/s. Hmm, my knowledge of OpenSSL is so little that it is well possible that I did it wrong. I have attached the small patch I used; can you see where I went wrong? Yours, Laurenz Albe
Attachment
On 04.11.2011 10:43, Albe Laurenz wrote: > Marti Raudsepp wrote: >>> Disabling OpenSSL compression in the source (which >>> is possible since OpenSSL 1.0.0) does not give me any performance >>> improvement. >> >> If it doesn't give you any performance improvement then you haven't >> disabled compression. Modern CPUs can easily saturate 1 GbitE with >> AES256-encrypted connections. Compression is usually the bottleneck, >> at 20-30 MB/s. > > Hmm, my knowledge of OpenSSL is so little that it is well possible that > I did it wrong. I have attached the small patch I used; can you see > where I went wrong? That only works with OpenSSL 1.0.0 - did you upgrade? I thought you were using 0.9.7a earlier. FWIW, it would be better to test "#ifdef SSL_OP_NO_COMPRESSION" directly, rather than the version number. -- Heikki Linnakangas EnterpriseDB http://www.enterprisedb.com
Heikki Linnakangas wrote: >>>> Disabling OpenSSL compression in the source (which >>>> is possible since OpenSSL 1.0.0) does not give me any performance >>>> improvement. >>> If it doesn't give you any performance improvement then you haven't >>> disabled compression. Modern CPUs can easily saturate 1 GbitE with >>> AES256-encrypted connections. Compression is usually the bottleneck, >>> at 20-30 MB/s. >> Hmm, my knowledge of OpenSSL is so little that it is well possible that >> I did it wrong. I have attached the small patch I used; can you see >> where I went wrong? > That only works with OpenSSL 1.0.0 - did you upgrade? I thought you were > using 0.9.7a earlier. > > FWIW, it would be better to test "#ifdef SSL_OP_NO_COMPRESSION" > directly, rather than the version number. Yes, I ran these tests with RHEL6 and OpenSSL 1.0.0. I guess I have hit the wall here. I can't get oprofile to run on this RHEL6 box, it doesn't record anything, so all I can test is total query duration. I tried to disable compression as above, but cannot verify that I was successful. I also tried different ciphers, but no matter what I did, the duration on the server stayed pretty much the same, 4 to 5 times more than without SSL. Thanks everybody for the help. Yours, Laurenz Albe
On Tue, Nov 8, 2011 at 12:25, Albe Laurenz <laurenz.albe@wien.gv.at> wrote: > I can't get oprofile to run on this RHEL6 box, it doesn't record > anything, so all I can test is total query duration. Maybe this helps you with OProfile? http://people.planetpostgresql.org/andrew/index.php?/archives/224-The-joy-of-Vx.html Regards, Marti
Marti Raudsepp wrote: >> I can't get oprofile to run on this RHEL6 box, it doesn't record >> anything, so all I can test is total query duration. > Maybe this helps you with OProfile? > > http://people.planetpostgresql.org/andrew/index.php?/archives/224-The-joy-of-Vx.html Dang, you're right, I wasn't aware that I was on a virtual machine.... Now it seems that you were right before as well, and I failed to disable SSL compression. At any rate this is what oprofile gives me: samples % image name symbol name 6754 83.7861 libz.so.1.2.3 /lib64/libz.so.1.2.3 618 7.6665 libcrypto.so.1.0.0 /usr/lib64/libcrypto.so.1.0.0 534 6.6245 postgres hex_encode 95 1.1785 libc-2.12.so memcpy Unfortunately there is hardly any documentation for OpenSSL, but I'll try to figure out what I did wrong. If I managed to disable compression, I think that would be good for pretty much everybody who uses SSL with PostgreSQL. Yours, Laurez Albe
Marti Raudsepp wrote: >> Disabling OpenSSL compression in the source (which >> is possible since OpenSSL 1.0.0) does not give me any performance >> improvement. > If it doesn't give you any performance improvement then you haven't > disabled compression. Modern CPUs can easily saturate 1 GbitE with > AES256-encrypted connections. Compression is usually the bottleneck, > at 20-30 MB/s. I finally managed to disable compression, and the performance improvement is dramatic. Now I have "only" 100% penalty for using SSL, as seen in this oprofile report: samples % image name symbol name 751 50.1670 libcrypto.so.1.0.0 /usr/lib64/libcrypto.so.1.0.0 594 39.6794 postgres hex_encode 83 5.5444 libc-2.12.so memcpy I'll post to hackers and see if I can get this into core. Yours, Laurenz Albe