New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Slow SSL Authentication on Ubuntu 16.04 / 18.04 #32888

Open
karmeli87 opened this Issue Oct 18, 2018 · 11 comments

Comments

Projects
None yet
6 participants
@karmeli87

karmeli87 commented Oct 18, 2018

We investigate errors during SSL authentication on ubuntu using kestrel.
We initiate many concurrent connections and observer that we hang on AuthenticateAsClientAsync and AuthenticateAsServerAsync.
While trying to make a minimal repo, we decided to do a simple sever-client app that simulate our usage.

Running the same app on windows resulted in:
Plain ~20ms
SSL ~200ms

while on ubuntu 18.04:
Plain ~1s
SSL ~40s

I also tried on a VM running 16.04
Plain ~1s
SSL ~5s

In all of the test the dotnet version is 2.1.403

using System;
using System.Net;
using System.Diagnostics;
using System.Net.Sockets;
using System.Security.Cryptography.X509Certificates;
using System.Threading;
using System.Threading.Tasks;

namespace ConsoleApp1
{
    public static class Program
    {
        public static void Main(string[] args)
        {
#if USE_SSL
        System.Console.WriteLine("SSL");
#else
            Console.WriteLine("Plain");
#endif
            var globalCertificate = new X509Certificate2("path/to/cert.pfx");
            var listener = new TcpListener(new IPAddress(new byte[] { 127, 0, 0, 1 }), 56789);
            listener.Start();
            for (var i = 0; i < 1; i++)
                Listen(listener, globalCertificate);
            var overall = Stopwatch.StartNew();
            int done = 0;
            int failed = 0;
            var clients = 200;
            var tasks = new Task[clients];
            for (int i = 0; i < clients; i++)
            {
                var j = i;
                tasks[i] = Task.Run(async () =>
                {
                    var sp = Stopwatch.StartNew();
                    try
                    {
                        using (var tcpClient = new TcpClient())
                        {
                            await tcpClient.ConnectAsync(new IPAddress(new byte[] { 127, 0, 0, 1 }), 56789);
#if USE_SSL
                            using (var wrapped = new SslStream(tcpClient.GetStream(), false, ((sender, certificate, chain, errors) => true)))
                            {
                                await wrapped.AuthenticateAsClientAsync("localhost", new X509CertificateCollection(new[] {globalCertificate}),
                                    SslProtocols.Tls12, false);
#else
                            using (var wrapped = tcpClient.GetStream())
                            {
#endif
                                byte[] buffer = { 1 };
                                await wrapped.WriteAsync(buffer, 0, 1);
                                var read = await wrapped.ReadAsync(buffer, 0, 1);

                                if (read != 1)
                                {
                                    Console.WriteLine("why?");
                                }

                                Interlocked.Increment(ref done);
                            }
                        }
                    }
                    catch (Exception e)
                    {
                        Console.WriteLine(Interlocked.Increment(ref failed) + " FAILED " + sp.Elapsed);
                        Console.WriteLine(e);
                    }
                });
            }

            Task.WaitAll(tasks);

            Console.WriteLine("Done " + done + " failed " + failed + " in " + overall.Elapsed);
        }

        private static void Listen(TcpListener listener, X509Certificate globalCertificate)
        {
            Task.Run(async () =>
            {

                try
                {
                    var tcpClient = await listener.AcceptTcpClientAsync();
                    Listen(listener, globalCertificate);

#if USE_SSL
                    using (var wrapped = new SslStream(tcpClient.GetStream(), false, ((sender, certificate, chain, errors) => true)))
                    {
                        await wrapped.AuthenticateAsServerAsync(globalCertificate);
#else
                    using (var wrapped = tcpClient.GetStream())
                    {
#endif

                        var buffer = new byte[1];

                        var read = await wrapped.ReadAsync(buffer, 0, 1);

                        await wrapped.WriteAsync(buffer, 0, 1);
                    }
                }
                catch (Exception e)
                {
                    Console.WriteLine(e);
                }
            });
        }
    }
}

@karmeli87 karmeli87 changed the title from Slow SLL Authentication on Ubuntu 16.04 / 18.04 to Slow SSL Authentication on Ubuntu 16.04 / 18.04 Oct 18, 2018

@karelz

This comment has been minimized.

Member

karelz commented Oct 18, 2018

Your .NET SDK version 2.1.403 corresponds to .NET Core 2.1.5: https://github.com/dotnet/core/blob/master/release-notes/2.1/2.1.5/2.1.5.md

Did you try to measure perf of 1 connection at a time? (ideally with BenchmarkDotNet to get stable results with reasonable statistics)
Is it consistent? Is it comparable between Windows and Ubuntu?

@karmeli87

This comment has been minimized.

karmeli87 commented Oct 19, 2018

Windows results

BenchmarkDotNet=v0.11.1, OS=Windows 10.0.17134.345 (1803/April2018Update/Redstone4)
Intel Core i7-8700K CPU 3.70GHz (Coffee Lake), 1 CPU, 12 logical and 6 physical cores
Frequency=3609377 Hz, Resolution=277.0561 ns, Timer=TSC
.NET Core SDK=2.1.403
  [Host]     : .NET Core 2.1.5 (CoreCLR 4.6.26919.02, CoreFX 4.6.26919.02), 64bit RyuJIT
  Job-WNQDRD : .NET Core 2.1.5 (CoreCLR 4.6.26919.02, CoreFX 4.6.26919.02), 64bit RyuJIT

MinIterationTime=1.0000 s  InvocationCount=1  UnrollFactor=1  
Method Clients UseSsl Mean Error StdDev Median
Logic 1 False 206.3 us 16.28 us 46.70 us 192.8 us
Logic 1 True 5,808.3 us 115.09 us 262.12 us 5,762.3 us
Logic 200 False 11,377.5 us 366.87 us 1,034.77 us 11,499.8 us
Logic 200 True 145,494.8 us 2,020.88 us 1,791.46 us 145,074.2 us

Ubuntu 16.04 VM

BenchmarkDotNet=v0.11.1, OS=ubuntu 16.04
Intel Core i7-8700K CPU 3.70GHz (Coffee Lake), 1 CPU, 4 logical and 4 physical cores
.NET Core SDK=2.1.403
  [Host]     : .NET Core 2.1.5 (CoreCLR 4.6.26919.02, CoreFX 4.6.26919.02), 64bit RyuJIT
  Job-TGPQPU : .NET Core 2.1.5 (CoreCLR 4.6.26919.02, CoreFX 4.6.26919.02), 64bit RyuJIT

MinIterationTime=1.0000 s  InvocationCount=1  UnrollFactor=1  
Method Clients UseSsl Mean Error StdDev
Logic 1 False 320.4 us 42.36 us 116.7 us
Logic 1 True 100,485.5 us 2,289.40 us 6,750.4 us
Logic 200 False 1,022,986.8 us 7,503.23 us 7,018.5 us
Logic 200 True 4,839,151.4 us 40,209.63 us 37,612.1 us

Real machine Ubuntu 18.04

BenchmarkDotNet=v0.11.1, OS=ubuntu 18.04
Intel Core i7-2600 CPU 3.40GHz (Sandy Bridge), 1 CPU, 8 logical and 4 physical cores
.NET Core SDK=2.1.403
  [Host]     : .NET Core 2.1.5 (CoreCLR 4.6.26919.02, CoreFX 4.6.26919.02), 64bit RyuJIT
  Job-SYOZYF : .NET Core 2.1.5 (CoreCLR 4.6.26919.02, CoreFX 4.6.26919.02), 64bit RyuJIT

MinIterationTime=1.0000 s  InvocationCount=1  UnrollFactor=1
Method Clients UseSsl Mean Error StdDev Median
Logic 1 False 211.8 us 17.77 us 51.56 us 200.8 us
Logic 1 True 667,490.7 us 1,924.58 us 1,706.09 us 667,549.8 us
Logic 200 False 932,487.9 us 98,382.48 us 282,277.78 us 1,017,976.7 us
Logic 200 True 35,283,175.3 us 61,730.03 us 54,722.06 us 35,281,549.3 us

This is first time I use BenchmarkDotNet so hope I got it correct :-)

using System;
using System.Net;
using System.IO;
using System.Net.Security;
using System.Net.Sockets;
using System.Security.Authentication;
using System.Security.Cryptography.X509Certificates;
using System.Threading.Tasks;
using BenchmarkDotNet.Attributes;
using BenchmarkDotNet.Running;

namespace ConsoleApp1
{
    public static class Program
    {
        [MinIterationTime(1000)]
        public class SslTest
        {
            public static X509Certificate2 GlobalCertificate = new X509Certificate2(@"cert.pfx");

            [Params(1, 200)]
            public  int Clients;

            [Params(false,true)]
            public bool UseSsl;

            public  int Port;

            public TcpListener Listener;

            [IterationSetup]
            public void Setup()
            {
                Listener = new TcpListener(IPAddress.Loopback, 0);
                Listener.Start();
                Port = ((IPEndPoint)Listener.LocalEndpoint).Port;

                for (var i = 0; i < 1; i++)
                    Listen(Listener, UseSsl);
            }
            [IterationCleanup]
            public void CleanUp()
            {
                Listener.Stop();
            }

            [Benchmark]
            public async Task Logic()
            {
                var tasks = new Task[Clients];
                for (int i = 0; i < Clients; i++)
                {
                    tasks[i] = Task.Run(async () =>
                    {
                        await SingleConnection(UseSsl);

                    });
                }

                await Task.WhenAll(tasks);
            }

            public async Task<Stream> WrapServer(TcpClient tcpClient, bool ssl)
            {
                var stream = tcpClient.GetStream();
                if (ssl == false)
                    return stream;

                var wrapped = new SslStream(tcpClient.GetStream(), false,
                    ((sender, certificate, chain, errors) => true));

                await wrapped.AuthenticateAsServerAsync(GlobalCertificate);
                return wrapped;
            }

            public async Task<Stream> WrapClient(TcpClient tcpClient, bool ssl)
            {
                var stream = tcpClient.GetStream();
                if (ssl == false)
                    return stream;

                var wrapped = new SslStream(stream, false, ((sender, certificate, chain, errors) => true));

                await wrapped.AuthenticateAsClientAsync("localhost",
                    new X509CertificateCollection(new X509Certificate[] {GlobalCertificate}),
                    SslProtocols.Tls12, false);
                return wrapped;
            }

            public async Task SingleConnection(bool ssl)
            {
                using (var tcpClient = new TcpClient())
                {
                    tcpClient.LingerState = new LingerOption(false, 0);
                    await tcpClient.ConnectAsync(IPAddress.Loopback, Port);
                    using (var wrapped = await WrapClient(tcpClient, ssl))
                    {
                        byte[] buffer = { 1 };
                        await wrapped.WriteAsync(buffer, 0, 1);
                        var read = await wrapped.ReadAsync(buffer, 0, 1);

                        if (read != 1)
                        {
                            Console.WriteLine("why?");
                        }
                    }
                }
            }

            private void Listen(TcpListener listener, bool ssl)
            {
                Task.Run(async () =>
                {
                    var tcpClient = await listener.AcceptTcpClientAsync();
                    Listen(listener, ssl);
                    tcpClient.LingerState = new LingerOption(false, 0);

                    using (var wrapped = await WrapServer(tcpClient, ssl))
                    {

                        var buffer = new byte[1];

                        var read = await wrapped.ReadAsync(buffer, 0, 1);

                        await wrapped.WriteAsync(buffer, 0, 1);
                    }
                });
            }
        }

        public static void Main(string[] args)
        {
            var summary = BenchmarkRunner.Run<SslTest>();
        }
    }
}
@ayende

This comment has been minimized.

Contributor

ayende commented Oct 23, 2018

What additional information is required?

@karelz

This comment has been minimized.

Member

karelz commented Oct 23, 2018

I think the information is sufficient. Next step is to do perf analysis to understand if the slowdown is something we can affect, or if it is inherently part of OpenSSL - in which case there is likely not much we can do.
What is the impact of the issue on your scenarios? (I assume it impacts RavenDB)

@karelz karelz removed the needs more info label Oct 23, 2018

@karelz

This comment has been minimized.

Member

karelz commented Oct 23, 2018

@ayende

This comment has been minimized.

Contributor

ayende commented Oct 23, 2018

@karelz The impact we have is that under load tests, we start seeing failures to connect to the RavenDB on Linux. Not because of anything that we do, but because the SSL authentication just takes so very long.

From analysis of the behavior, it looks like a convoy.

Can you point me to how you are doing perf analysis on Linux?
That is something that I haven't had the chance to do and I'll be happy to try to figure out what is actually going on, given a few hints on how to do that.

@karelz

This comment has been minimized.

Member

karelz commented Oct 23, 2018

That would be great!
Here is how to do perf investigations on Linux: https://github.com/dotnet/coreclr/blob/master/Documentation/project-docs/linux-performance-tracing.md
@adamsitnik should be able to help if needed.

BTW: The single connection numbers (667ms on real HW) worry me as well. It is 3,000x more than non-SSL. That does not look healthy at all. For comparison: your Linux VM is 300x and Windows 30x overhead of SSL.

@karelz

This comment has been minimized.

Member

karelz commented Oct 23, 2018

The numbers indicate bigger problem in the scale up of non-SSL connections on both Linux measurements:

  No SSL (1->200) SSL (1->200)
Windows 55x 25x
Ubuntu 16.04 VM 3,197x 48x
Ubuntu 18.04 HW 4,399x 52x
@geoffkizer

This comment has been minimized.

Member

geoffkizer commented Oct 23, 2018

Re methodology here: I'm always a little skeptical of tests where we spawn a lot (200, here) of tasks at the same time. The problem is that this introduces the added variable of task/thread pool scheduling, which has differences between Windows and Linux.

A better approach, IMO, is to spawn a fixed number of threads and have them loop over many iterations, then measure the overall throughput.

I do think it's likely we have a problem here, but I'd like to get numbers that better reflect the actual problem without introducing additional variables.

@andy-yx-chen

This comment has been minimized.

andy-yx-chen commented Oct 26, 2018

I can reproduce the same numbers here, SSL vs non SSL on Ubuntu 18.04 has 300x overhead, any progress had been made?

@wfurt

This comment has been minimized.

Member

wfurt commented Oct 26, 2018

I can probably take a look next week with mods @geoffkizer suggested.

@karelz karelz added this to the 3.0 milestone Nov 2, 2018

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment