Skip to content
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

X509Chain building is slow on Linux #28618

Closed
stephentoub opened this issue Feb 4, 2019 · 21 comments · Fixed by dotnet/corefx#37697
Closed

X509Chain building is slow on Linux #28618

stephentoub opened this issue Feb 4, 2019 · 21 comments · Fixed by dotnet/corefx#37697
Labels
area-System.Security bug os-linux Linux OS (any supported distro) tenet-performance Performance related issue
Milestone

Comments

@stephentoub
Copy link
Member

The boxes running this are not directly comparable, however the magnitude of the difference is such that it doesn't really matter.

On my Windows 10 machine, I get numbers like this:

1000 iterations: 00:00:00.1357884
1000 iterations: 00:00:00.1070347
1000 iterations: 00:00:00.1002223
1000 iterations: 00:00:00.1117821
1000 iterations: 00:00:00.1120664

On my Ubuntu 18.04 machine, I get numbers like this:

1000 iterations: 00:00:07.8729786
1000 iterations: 00:00:07.4546996
1000 iterations: 00:00:07.2997272
1000 iterations: 00:00:07.3354975
1000 iterations: 00:00:07.4212720

Repro:

using System;
using System.Diagnostics;
using System.Linq;
using System.Security.Cryptography.X509Certificates;

class Program
{
    static void Main()
    {
        const int Iters = 1000;

        var sw = new Stopwatch();
        using (X509Certificate2 originalCert = GetServerCertificate())
        {
            while (true)
            {
                Console.Write($"{Iters} iterations: ");
                sw.Restart();
                for (int i = 0; i < Iters; i++)
                {
                    using (var chain = new X509Chain())
                    using (var cert = new X509Certificate2(originalCert))
                    {
                        chain.Build(cert);
                    }
                }
                sw.Stop();
                Console.WriteLine(sw.Elapsed);
            }
        }
    }

    private static X509Certificate2 GetServerCertificate()
    {
        var certCollection = new X509Certificate2Collection();
        certCollection.Import(s_testCertBytes, "testcertificate", X509KeyStorageFlags.DefaultKeySet);
        return certCollection.Cast<X509Certificate2>().First(c => c.HasPrivateKey);
    }

    private static readonly byte[] s_testCertBytes = Convert.FromBase64String(@"MIIVBAIBAzCCFMAGCSqGSIb3DQEHAaCCFLEEghStMIIUqTCCCooGCSqGSIb3DQEHAaCCCnsEggp3MIIKczCCCm8GCyqGSIb3DQEMCgECoIIJfjCCCXowHAYKKoZIhvcNAQwBAzAOBAhCAauyUWggWwICB9AEgglYefzzX/jx0b+BLU/TkAVj1KBpojf0o6qdTXV42drqIGhX/k1WwF1ypVYdHeeuDfhH2eXHImwPTw+0bACY0dSiIHKptm0sb/MskoGI8nlOtHWLi+QBirJ9LSUZcBNOLwoMeYLSFEWWBT69k/sWrc6/SpDoVumkfG4pZ02D9bQgs1+k8fpZjZGoZp1jput8CQXPE3JpCsrkdSdiAbWdbNNnYAy4C9Ej/vdyXJVdBTEsKzPYajAzo6Phj/oS/J3hMxxbReMtj2Z0QkoBBVMc70d+DpAK5OY3et872D5bZjvxhjAYh5JoVTCLTLjbtPRn1g7qh2dQsIpfQ5KrdgqdImshHvxgL92ooC1eQVqQffMnZ0/LchWNb2rMDa89K9CtAefEIF4ve2bOUZUNFqQ6dvd90SgKq6jNfwQf/1u70WKE86+vChXMMcHFeKso6hTE9+/zuUPNVmbRefYAtDd7ng996S15FNVdxqyVLlmfcihX1jGhTLi//WuMEaOfXJ9KiwYUyxdUnMp5QJqO8X/tiwnsuhlFe3NKMXY77jUe8F7I+dv5cjb9iKXAT+q8oYx1LcWu2mj1ER9/b2omnotp2FIaJDwI40Tts6t4QVH3bUNE9gFIfTMK+WMgKBz/JAGvC1vbPSdFsWIqwhl7mEYWx83HJp/+Uqp5f+d8m4phSan2rkHEeDjkUaoifLWHWDmL94SZBrgU6yGVK9dU82kr7jCSUTrnga8qDYsHwpQ22QZtu0aOJGepSwZU7NZNMiyX6QR2hI0CNMjvTK2VusHFB+qnvw+19DzaDT6P0KNPxwBwp07KMQm3HWTRNt9u6gKUmo5FHngoGte+TZdY66dAwCl0Pt+p1v18XlOB2KOQZKLXnhgikjOwYQxFr3oTb2MjsP6YqnSF9EpYpmiNySXiYmrYxVinHmK+5JBqoQCN2C3N24slZkYq+AYUTnNST7Ib2We3bBICOFdVUgtFITRW40T+0XZnIv8G1Kbaq/1avfWI/ieKKxyiYp/ZNXaxc+ycgpsSsAJEuhb83bUkSBpGg9PvFEF0DXm4ah67Ja1SSTmvrCnrOsWZXIpciexMWRGoKrdvd7Yzj9E8hiu+CGTC4T6+7FxVXJrjCg9zU9G2U6g7uxzoyjGj1wqkhxgvl9pPbz6/KqDRLOHCEwRF4qlWXhsJy4levxGtifFt6n7DWaNSsOUf8Nwpi+d4fd7LQ7B5tW/y+/vVZziORueruCWO4LnfPhpJ70g18uyN7KyzrWy29rpE46rfjZGGt0WDZYahObPbw6HjcqSOuzwRoJMxamQb2qsuQnaBS6Bhb5PAnY4SEA045odf/u9uC7mLom2KGNHHz6HrgEPas2UHoJLuxYvY1pza/29akuVQZQUvMA5yMFHHGYZLtTKtCGdVGwX0+QS6ovpV93xux4I/5TrD5U8z9RmTdAx03R3MUhkHF7Zbv5egDNsVar+41YWG4VkV1ZXtsZRKJf0hvKNvrpH0e7fVKBdXljm5PXOSg2VdtkhhOpnKKSMcv6MbGWVi/svWLnc7Qim4A4MDaz+bFVZmh3oGJ7WHvRQhWIcHUL+YJx+064+4IKXZJ/2a/+b2o7C8mJ3GGSBx831ADogg6MRWZx3UY19OZ8YMvpzmZEBRZZnm4KgNpj+SQnf6pGzD2cmnRhzG60LSNPb17iKbdoUAEMkgt2tlMKXpnt1r7qwsIoTt407cAdCEsUH7OU/AjfFmSkKJZ7vC5HweqZPnhgJgZ6LYHlfiRzUR1xeDg8JG0nb0vb7LUE4nGPy39/TxIGos7WNwGpG1QVL/8pKjFdjwREaR8e5CSTlQ7gxHV+G3FFvFGpA1p8cRFzlgE6khDLrSJIUkhkHMA3oFwwAzBNIKVXjToyxCogDqxWya0E1Hw5rVCS/zOCS1De2XQbXs//g46TW0wTJwvgNbs0xLShf3XB+23meeEsMTCR0+igtMMMsh5K/vBUGcJA27ru/KM9qEBcseb/tqCkhhsdj1dnH0HDmpgFf5DfVrjm+P6ickcF2b+Ojr9t7XHgFszap3COpEPGmeJqNOUTuU53tu/O774IBgqINMWvvG65yQwsEO06jRrFPRUGb0eH6UM4vC7wbKajnfDuI/EXSgvuOSZ9wE8DeoeK/5We4pN7MSWoDl39gI/LBoNDKFYEYuAw/bhGp8nOwDKki4a16aYcBGRClpN3ymrdurWsi7TjyFHXfgW8fZe4jXLuKRIk19lmL1gWyD+3bT3mkI2cU2OaY2C0fVHhtiBVaYbxBV8+kjK8q0Q70zf0r+xMHnewk9APFqUjguPguTdpCoH0VAQST9Mmriv/J12+Y+fL6H+jrtDY2zHPxTF85pA4bBBnLA7Qt9TKCe6uuWu5yBqxOV3w2Oa4Pockv1gJzFbVnwlEUWnIjbWVIyo9vo4LBd03uJHPPIQbUp9kCP/Zw+Zblo42/ifyY+a+scwl1q1dZ7Y0L92yJCKm9Qf6Q+1PBK+uU9pcuVTg/Imqcg5T7jFO5QCi88uwcorgQp+qoeFi0F9tnUecfDl6d0PSgAPnX9XA0ny3bPwSiWOA8+uW73gesxnGTsNrtc1j85tail8N6m6S2tHXwOmM65J4XRZlzzeM4D/Rzzh13xpRA9kzm9T2cSHsXEYmSW1X7WovrmYhdOh9K3DPwSyG4tD58cvC7X79UbOB+d17ieo7ZCj+NSLVQO1BqTK0QfErdoVHGKfQG8Lc/ERQRqj132Mhi2/r5Ca7AWdqD7/3wgRdQTJSFXt/akpM44xu5DMTCISEFOLWiseSOBtzT6ssaq2Q35dCkXp5wVbWxkXAD7Gm34FFXXyZrJWAx45Y40wj/0KDJoEzXCuS4Cyiskx1EtYNNOtfDC5wngywmINFUnnW0NkdKSxmDJvrT6HkRKN8ftik7tP4ZvTaTS28Z0fDmWJ+RjvZW+vtF6mrIzYgGOgdpZwG0ZOSKrXKrY3xpMO16fXyawFfBosLzCty7uA57niPS76UXdbplgPanIGFyceTg1MsNDsd8vszXd4KezN2VMaxvw+93s0Uk/3Mc+5MAj+UhXPi5UguXMhNo/CU7erzyxYreOlAI7ZzGhPk+oT9g/MqWa5RpA2IBUaK/wgaNaHChfCcDj/J1qEl6YQQboixxp1IjQxiV9bRQzgwf31Cu2m/FuHTTkPCdxDK156pyFdhcgTpTNy7RPLDGB3TATBgkqhkiG9w0BCRUxBgQEAQAAADBdBgkrBgEEAYI3EQExUB5OAE0AaQBjAHIAbwBzAG8AZgB0ACAAUwB0AHIAbwBuAGcAIABDAHIAeQBwAHQAbwBnAHIAYQBwAGgAaQBjACAAUAByAG8AdgBpAGQAZQByMGcGCSqGSIb3DQEJFDFaHlgAQwBlAHIAdABSAGUAcQAtADcAOQA4AGUANQA4AGIANQAtAGMAOQA2ADQALQA0ADcAZQA2AC0AYQAzADIAOQAtADAAMQBjAGEAZABmADcANgAyAGEANgA5MIIKFwYJKoZIhvcNAQcGoIIKCDCCCgQCAQAwggn9BgkqhkiG9w0BBwEwHAYKKoZIhvcNAQwBBjAOBAh+t0PMVhyoagICB9CAggnQwKPcfNq8ETOrNesDKNNYJVXnWoZ9Qjgj9RSpj+pUN5I3B67iFpXClvnglKbeNarNCzN4hXD0I+ce+u+Q3iy9AAthG7uyYYNBRjCWcBy25iS8htFUm9VoV9lH8TUnS63Wb/KZnowew2HVd8QI/AwQkRn8MJ200IxR/cFD4GuVO/Q76aqvmFb1BBHItTerUz7t9izjhL46BLabJKx6Csqixle7EoDOsTCA3H1Vmy2/Hw3FUtSUER23jnRgpRTA48M6/nhlnfjsjmegcnVBoyCgGaUadGE5OY42FDDUW7wT9VT6vQEiIfKSZ7fyqtZ6n4+xD2rVySVGQB9+ROm0mywZz9PufsYptZeB7AfNOunOAd2k1F5y3qT0cjCJ+l4eXr9KRd2lHOGZVoGq+e08ylBQU5HB+Tgm6mZaEO2QgzXOAt1ilS0lDii490DsST62+v58l2R45ItbRiorG/US7+HZHjHUY7EsDUZ+gn3ZZNqh1lAoli5bC1xcjEjNdqq0knyCAUaNMG59UhCWoB6lJpRfVEeQOm+TjgyGw6t3Fx/6ulNPc1V/wcascmahH3kgHL146iJi1p2c2yIJtEB+4zrbYv7xH73c8qXVh/VeuD80I/+QfD+GaW0MllIMyhCHcduFoUznHcDYr5GhJBhU62t6sNnSjtEU1bcd20oHrBwrpkA7g3/Mmny33IVrqooWFe876lvQVq7GtFu8ijVyzanZUs/Cr7k5xX3zjh6yUMAbPiSnTHCl+SEdttkR936fA6de8vIRRGj6eAKqboRxgC1zgsJrj7ZVI7h0QlJbodwY2jzyzcC5khn3tKYjlYeK08iQnzeK5c9JVgQAHyB4uOyfbE50oBCYJE7npjyV7LEN2f7a3GHX4ZWI3pTgbUv+Q1t8BZozQ4pcFQUE+upYucVL3Fr2T8f7HF4G4KbDE4aoLiVrYjy0dUs7rCgjeKu21UPA/BKx4ebjG+TZjUSGf8TXqrJak1PQOG4tExNBYxLtvBdFoOAsYsKjTOfMYpPXp4vObfktFKPcD1dVdlXYXvS5Dtz3qEkwmruA9fPQ6FYi+OFjw0Pkwkr5Tz+0hRMGgb1JRgVo8SVlW/NZZIEbKJdW5ZVLyMzdd1dC0ogNDZLPcPR/HENe2UXtq+0qQw0ekZ+aC2/RvfAMr5XICX8lHtYmQlAFGRhFNuOysHj7V2AJTuOx2wCXtGzrTPc6eyslsWyJign8bD1r+gkejx/qKBwwTvZF1aSmiQmFnmMm0jLj7n8v7v6zHCFTuKF1bHZ44eIwMaUDl6MAgHDdvkPl56rYgq/TM3dKuXnu47GLiRei0EXTT9OMCKcI6XYICsge81ET3k15VfLyI1LNufgqAsafnwl31yqntscXW0NsxW6SkmyXaW1mndxejLBQRjik3civBGTgxgKQbZaO9ZGOrjsSogcCSne+s0zLDxEFjmaYYtpIaU8SFWDja5jyo0jvM3OHUwvElvndZJgreFGG5cKHgwgGKdkYgx6YAvucrgQwqKE/+nxuhkKWtV9D4h9qFAqZbWc9jOPtWx9h3U3gX3NTLY/4Z4iy/FXR9KnKUtCmD1MSRRIOiMca1sNTga3mP/+qSS5u+pyon5c4c/jLdEW0GapDz/yvQcc0MP/21vSoeIkUN+w/RzUBvxrawhHGx+FeLlI249+LBKNBQu4Fbw6G9AYpPJf3PdNc0GRMnantA4B7Rm2NsSGdqqrEMuCw1XxzR6ki4jbLC/ASbcVMr54YsBw+45sggenFshRrYm0QXoUM5XoqEtesby6YfPAjBldyB/QcuULV6QyAeL44YmxOnKD5E5qQwgfcZUxN01eBgbeSS7bZI3zpFwAMdMQ+dtwHXMuhVXuUGLmNTvNe9DupfPGKbaM8louY1Xw4fmg4PaY7MP2mdYQlEXvSg2geICJVuGRBirH+Xv8VPr7lccN++LXv2NmggoUo/d18gvhY8XtOrOMon1QGANPh7SzBjR3v19JD170Z6GuZCLtMh681YkKwW/+Em5rOtexoNQRTjZLNSTthtMyLfAqLk6lZnbbh+7VdCWVfzZoOzUNV+fVwwvyR9ouIzrvDoZ5iGRZU8rEuntap6rBrf9F3FMsz4mvPlCAMp15sovLFpVI8t+8OmKmqQH3LOwd03s6iMJ+0YEWrCaTQYu3kEKoOWC3uhGE8XLSjZBqc3kwVIlzVzOBr97SGjG88JYVDW2FrjQbIv+1yTzOYzMnCDUW3T8GMtfYEQbN6ZtBaD9i4ZeZlQCdkfGuNC6OYO98L7fU4frgff8nNfeka8kHtvNMn4CosFKBRXA5y+kqEE0Qk5feZhfM8NX9x3O0CJobm4HC57VxJ3c0jTe2SA0gAfB4g0keghmDzYgjQAuIY/o1LMKFiBNue4fnXlhU1L402Zlx/lzKDera6o3Xgh9IXj3ZqyFlXa9bkyKDtek0ephTZulLc3NLeb1a3KZxId8OmplR8OcZsHluEu+Z3Der0j8Ro7X7kOnNkUxuTV2blqZ4V8DsYKATeKv4ffc1Ub8MLBd9hMs8ehjmC5jkYApM5HvXl4411mPN6MrF8f2hPVgqrd3p/M80c8wNWjvWIvPLr9Tjqk71hKBq3+Hu0oI1zuoTY2BOhBLyvpjM+mvRd8UlrFJTLGTyCAXvAhIDRIVyrGuscO5Y0sfDc+82Bvrua4FyhZkjb1r8GrGciH0V5HHKjg5dewWnr21qf4q96yf2/ZjoldFFvKiCd8wum9ZV1OaTbjjg46oSpIyBzxl4qpfrgT1ZX1MvGW4uAJ7WQHjSAex7VGr1Sl+ghe5PQBbURyFiu9PnBRMOMjGYkI2lngd3bdehc+i2fPnNe5LgdsBbmUKmEJH96rlkFT8Co+NYBWKBUsBXyfC+kwXDRyNrt2r7VafWWz/cwK0/AJ/Ucq4vz8E0mzy03Gs+ePW+tP9JOHP6leF0TLhbItvQl3DJy0gj6TyrO9S077EVyukFCXeH1/yp04lmq4G0urU+pUf2wamP4BVNcVsikPMYo/e75UI330inXG4+SbJ40q/MQIfYnXydhVmWVCUXkfRFNbcCu7JclIrzS1WO26q6BOgs2GhA3nEan8CKxa85h/oCaDPPMGhkQtCU75vBqQV9Hk2+W5zMSSj7R9RiH34MkCxETtY8IwKa+kiRAeMle8ePAmT6HfcBOdTsVGNoRHQAOZewwUycrIOYJ/54WOmcy9JZW9/clcgxHGXZq44tJ3BDHQQ4qBgVd5jc9Qy9/fGS3YxvsZJ3iN7IMs4Jt3GWdfvwNpJaCBJjiiUntJPwdXMjAeUEZ16Tmxdb1l42rjFSCptMJS2N2EPSNb36+staNgzflctLLpmyEK4wyqjA7MB8wBwYFKw4DAhoEFIM7fHJcmsN6HkU8HxypGcoifg5MBBRXe8XL349R6ZDmsMhpyXbXENCljwICB9A=");
}

cc: @bartonjs

@stephentoub
Copy link
Member Author

Related to dotnet/aspnetcore#7081.

@bartonjs
Copy link
Member

bartonjs commented Feb 4, 2019

#15113 is going to change this code a bit; looking at perf here probably doesn't make sense until after that's done.

@vancem
Copy link
Contributor

vancem commented Feb 4, 2019

Do we know if #15113 is really funded (it is marked as 3.0, is someone working on it?)?

Note that the difference in perf is a ~700X. Do we have any reason to believe the Linux implementation is that much worse? My guess is that there is some caching that happens on Windows that is not happening on Linux.

It would be good to at least understand the rough architectural blocks involved. My guess is that #15113 (which is about status checking an X509 certificate) is probably independent (or maybe actually makes caching harder). Ideally we confirm or deny my guess above, and if we determine that it is caching and roughly independent of #15113 (and relatively easy), we should go to some trouble to do that first if #15113 is in any danger of being cut.

@bartonjs
Copy link
Member

bartonjs commented Feb 4, 2019

Do we know if #15113 is really funded (it is marked as 3.0, is someone working on it?)?

Essentially it's needed because Let's Encrypt is popular and only does OCSP; so there'll be a big kerfuffle with security signoff if it doesn't get done. So... yes, me :).

Note that the difference in perf is a ~700X.

~75x. But on different machines; and I'm guessing the Linux one is a VM.

Do we have any reason to believe the Linux implementation is that much worse?

For an average cert chain Windows has to do ~5 P/Invoke transitions, on Linux we do ~500, mostly because of trying to piece back together the shape that the API forces us to return data.

My guess is that #15113 (which is about status checking an X509 certificate) is probably independent (or maybe actually makes caching harder).

There's an inversion of control needed to bring the feature online, and taking the new needs into consideration along with the perf delta an optimization for the successful chain case will likely result in bringing the OpenSSL version down to ~5 P/Invokes.

So really the comment is "I'm already going to be doing a lot of work in that space, no one should touch it until I'm done".

@stephentoub
Copy link
Member Author

I'm guessing the Linux one is a VM

It is, in Azure. It's a "Standard D4s v3 (4 vcpus, 16 GB memory)".

@vancem
Copy link
Contributor

vancem commented Feb 4, 2019

Thanks @bartonjs, you put my mind at ease. My main concern was that we were making this work item dependent on a work item which was not clear had an owner. You confirmed you are the owner, understand why the current implementation is slow, and have strong reasons to believe that the work you will do will also fix this. I am happy...

Thanks

@yanrez
Copy link

yanrez commented May 7, 2019

Is this still on your radar for .net core 3? I wanted to track the progress for dotnet/aspnetcore#7081 , but can't find the right dashboard metric in powerbi.

@bartonjs
Copy link
Member

bartonjs commented May 7, 2019

Yes, seeing if it can be improved further (some ideas come to mind) is still in scope for 3.0.

@bartonjs bartonjs self-assigned this May 14, 2019
@bartonjs
Copy link
Member

Today's investigation says that if LM\Root, LM\CA, CU\Root, CU\CA, and CU\My were all built into permanently cached STACK_OF(X509*) values (SafeX509StackHandle) that tight-loop chains move from ~30ms to ~0.95ms on my test machine (1001 iterations, discounting the first one from the sample set) when the chain is valid and no revocation checks are performed.

Ideally the cache invalidation logic won't add too much back to that.

@bartonjs
Copy link
Member

@sebastienros / @halter73 : FYI, a big perf improvement just went in for X509Chain.Build on Linux. Using one of @stephentoub's SslStream tests we saw about 4 minutes reduction on 10,000 handshakes, ~24ms per. Hopefully your TLS benchmarks agree when you get a build with this change.

@sebastienros
Copy link
Member

If you can share the built assets I can give you a before/after comparison.

FYI current graph comparing Windows to Linux

image

@ccic
Copy link

ccic commented May 22, 2019

@sebastienros From your graph, it looks like X509Chain.Build for Linux still has a big performance gap compared with on Windows. Anyway, my project has suffered from this issue, how can I verify the fix in my local environment? shall I try dotnet core nightly build?

@ccic
Copy link

ccic commented May 22, 2019

I run @stephentoub's above test "X509Chain build" with dotnet 3.0 nightly build 3.0.100-preview6-012026, and see huge improvement.

My question is do you have a plan to backport to dotnet core 2.1, 2.2?

After the fix:
1000 iterations: 00:00:00.0974405
1000 iterations: 00:00:00.0484670
1000 iterations: 00:00:00.0442556
1000 iterations: 00:00:00.0457606
1000 iterations: 00:00:00.0490085

Before the fix:
1000 iterations: 00:00:03.4504450
1000 iterations: 00:00:03.3203837
1000 iterations: 00:00:03.3208841
1000 iterations: 00:00:03.3144381
1000 iterations: 00:00:03.3357802

@stephentoub
Copy link
Member Author

do you have a plan to backport to dotnet core 2.1, 2.2?

There is no plan to do so.

@yanrez
Copy link

yanrez commented May 22, 2019

Thanks for such a huge improvement!

@sebastienros
Copy link
Member

@ccic the nightly builds and docker images should have this change by now

@ccic
Copy link

ccic commented May 28, 2019

@stephentoub @bartonjs
When I use dotnet 3.0 preview on another Ubuntu VM (on Azure), I cannot reproduce the improvement. It takes about 3 seconds for every 1000 iteration. I found it connects to "apps.digsigtrust.com" when the @stephentoub's test "X509Chain build" is running.

But on my local VM which shows huge improvement never connects "apps.digsigtrust.com".

Is there anything wrong for my environment?

Those two VMs are: Ubuntu 16.04.4 LTS
dotnet core version: 3.0.100-preview6-012026
OpenSSL version: OpenSSL 1.1.1 11 Sep 2018

@bartonjs
Copy link
Member

@ccic If you're seeing activity on EVERY request, that suggests that either

a) The Azure VM doesn't trust the root, so ends up not caching data.
b) The disk is not writable (full, readonly, etc) so caching fails.

The only "intermittent" thing I can envision is OCSP/CRL expiry, if revocation is enabled on your tests. And the only thing I could think that would be different is that the Azure VM ends up hitting a different physical endpoint (due to routing rules) and receives a different response than your faster/successful machine.

@ccic
Copy link

ccic commented May 30, 2019

@bartonjs I wonder why the caching fails, so I did more tests, and found it may be related to the certificate. Only Chain build for "Let's Encrypt certificate" is very slow. My previous test run"Let's Encrypt certificate" on Azure VM, but run @stephentoub's test embedded certificate on local VM, that is not correct.

I have 2 certificates to check: @stephentoub's test embedded certificate (embedded in above source code), and Let's Encrypt certificate.

When I run Chain build perf test on Let's Encrypt certificate, it takes >3 seconds for 1000 iterations and connects to "apps.digsigtrust.com", but for @stephentoub's test embedded certificate, it takes ~0.05 seconds for 1000 iterations.

Experiments:

Apart from Chain build perf test, I added another function to check the certificate status information.

static void FunctionTest1(X509Certificate2 originalCert)
{
        var sw = new Stopwatch();
        {
            sw.Restart();
            using (var chain = new X509Chain())
            using (var cert = new X509Certificate2(originalCert))
            {
                var policy = chain.ChainPolicy;
                Console.WriteLine(policy.RevocationFlag);
                Console.WriteLine(policy.RevocationMode);
                Console.WriteLine(policy.UrlRetrievalTimeout);
                Console.WriteLine(policy.VerificationFlags);
                Console.WriteLine(policy.VerificationTime);
                if (!chain.Build(cert))
                {
                    Console.WriteLine("Certificate is invalid");
                }
                else
                {
                    Console.WriteLine("Certificate is valid");
                }
                foreach (var stat in chain.ChainStatus)
                {
                    Console.WriteLine(stat.StatusInformation);
                }
                if (!cert.Verify())
                {
                    Console.WriteLine("Basic certificate verify failed");
                }
                else
                {
                    Console.WriteLine("Basic certificate verify successfully");
                }
                Console.WriteLine(cert.ToString());
            }
            sw.Stop();
            Console.WriteLine(sw.Elapsed);
        }
}

I run all the certificates check on Windows 10 machine, Ubuntu 16.04 local VM (openssl 1.1.1), and Azure Ubuntu 18.04 VM (openssl 1.1.1). I found "Let us Encrypt certificate" shows different behavior compared with the another certificate.

@stephentoub's test embedded certificate and my service certificate on Windows 10 are invalid, and the revocation function does not work properly.

ExcludeRoot
Online
00:00:00
NoFlag
5/30/2019 10:32:21 AM
Certificate is invalid
A certificate chain could not be built to a trusted root authority
The revocation function was unable to check revocation for the certificate
The revocation function was unable to check revocation because the revocation server was offline
Basic certificate verify failed
[Subject]
  CN=testservereku.contoso.com

[Issuer]
  CN=NDX Test Root CA

[Serial Number]
  54000000320F036BF59292AA2F000000000032

[Not Before]
  12/30/2016 4:43:49 AM

[Not After]
  12/30/2036 4:53:49 AM

[Thumbprint]
  3D68C9DB575E6FDB56A81AE43B014E129349E024

00:00:00.1004160

Let's Encrypt certificate on windows 10 is valid, and does revocation check.

ExcludeRoot
Online
00:00:00
NoFlag
5/30/2019 10:36:13 AM
Certificate is valid
Basic certificate verify successfully
[Subject]
  CN=tlsperf.signalr.pro

[Issuer]
  CN=Let's Encrypt Authority X3, O=Let's Encrypt, C=US

[Serial Number]
  03D96E3BEEFD35BBF2DEF59B16FD49BA943C

[Not Before]
  5/29/2019 10:53:52 AM

[Not After]
  8/27/2019 10:53:52 AM

[Thumbprint]
  84C91D04BA81AFC678E4AC41C38D8F93F53EEA53

00:00:00.0624163

On Ubuntu, all certificates are invalid and "unable to get certificate CRL"
@stephentoub's test embedded certificate on Ubuntu 16.04 and 18.04 has the same output

ExcludeRoot
Online
00:00:00
NoFlag
5/30/2019 2:38:59 AM
Certificate is invalid
unable to get certificate CRL
unable to get local issuer certificate
Basic certificate verify failed
[Subject]
  CN=testservereku.contoso.com

[Issuer]
  CN=NDX Test Root CA

[Serial Number]
  54000000320F036BF59292AA2F000000000032

[Not Before]
  12/29/2016 8:43:49 PM

[Not After]
  12/29/2036 8:53:49 PM

[Thumbprint]
  3D68C9DB575E6FDB56A81AE43B014E129349E024

00:00:00.0997768

Let's Encrypt certificate also has the same output on Ubuntu 16.04 and Ubuntu 18.04, either local VM or Azure VM

ExcludeRoot
Online
00:00:00
NoFlag
5/30/2019 2:37:50 AM
Certificate is invalid
unable to get certificate CRL
unable to get local issuer certificate
Basic certificate verify failed
[Subject]
  CN=tlsperf.signalr.pro

[Issuer]
  CN=Let's Encrypt Authority X3, O=Let's Encrypt, C=US

[Serial Number]
  03D96E3BEEFD35BBF2DEF59B16FD49BA943C

[Not Before]
  5/29/2019 2:53:52 AM

[Not After]
  8/27/2019 2:53:52 AM

[Thumbprint]
  84C91D04BA81AFC678E4AC41C38D8F93F53EEA53

00:00:00.9755910

@bartonjs
Copy link
Member

@ccic If your system isn't considering Let's Encrypt as trusted that'll definitely throw things off.

I can't explain the "apps.digsigtrust.com", since that's not part of the Let's Encrypt infrastructure.

A better printing of the chain is

                    Console.WriteLine("Chain Element Status:");
                    foreach (X509ChainElement element in chain.ChainElements)
                    {
                        Console.Write("  ");
                        Console.WriteLine(element.Certificate.Subject);

                        foreach (X509ChainStatus status in element.ChainElementStatus)
                        {
                            Console.WriteLine("    {0} ({1})", status.Status, status.StatusInformation);
                        }

                        Console.WriteLine();
                    }

                    Console.WriteLine("Chain Summary:");

                    foreach (X509ChainStatus status in chain.ChainStatus)
                    {
                        Console.WriteLine("    {0} ({1})", status.Status, status.StatusInformation);
                    }

At least the part where it shows the elements. Somewhere you're not getting good chains; but that seems more to be system configuration than anything else.

@ccic
Copy link

ccic commented May 30, 2019

@bartonjs I checked "apps.digsigtrust.com" whose IP is 192.35.177.64, and it points to https://www.identrust.com/. I found Let's Encrypt used idenTrust to cross sign its certificate. See https://letsencrypt.org/certificates.

I checked the certificate of chain1.pem(https://letsencrypt.org/certs/lets-encrypt-x3-cross-signed.pem.txt) with openssl command: openssl x509 -in chain1.pem -noout -text
It looks like during Chain build, it always wants to connect idenTrust to verify CA.

I'm investigating further why this happens.

Certificate:
    Data:
        Version: 3 (0x2)
        Serial Number:
            0a:01:41:42:00:00:01:53:85:73:6a:0b:85:ec:a7:08
        Signature Algorithm: sha256WithRSAEncryption
        Issuer: O = Digital Signature Trust Co., CN = DST Root CA X3
        Validity
            Not Before: Mar 17 16:40:46 2016 GMT
            Not After : Mar 17 16:40:46 2021 GMT
        Subject: C = US, O = Let's Encrypt, CN = Let's Encrypt Authority X3
        Subject Public Key Info:
            Public Key Algorithm: rsaEncryption
                RSA Public-Key: (2048 bit)
                Modulus:
                    00:9c:d3:0c:f0:5a:e5:2e:47:b7:72:5d:37:83:b3:
                    68:63:30:ea:d7:35:26:19:25:e1:bd:be:35:f1:70:
                    92:2f:b7:b8:4b:41:05:ab:a9:9e:35:08:58:ec:b1:
                    2a:c4:68:87:0b:a3:e3:75:e4:e6:f3:a7:62:71:ba:
                    79:81:60:1f:d7:91:9a:9f:f3:d0:78:67:71:c8:69:
                    0e:95:91:cf:fe:e6:99:e9:60:3c:48:cc:7e:ca:4d:
                    77:12:24:9d:47:1b:5a:eb:b9:ec:1e:37:00:1c:9c:
                    ac:7b:a7:05:ea:ce:4a:eb:bd:41:e5:36:98:b9:cb:
                    fd:6d:3c:96:68:df:23:2a:42:90:0c:86:74:67:c8:
                    7f:a5:9a:b8:52:61:14:13:3f:65:e9:82:87:cb:db:
                    fa:0e:56:f6:86:89:f3:85:3f:97:86:af:b0:dc:1a:
                    ef:6b:0d:95:16:7d:c4:2b:a0:65:b2:99:04:36:75:
                    80:6b:ac:4a:f3:1b:90:49:78:2f:a2:96:4f:2a:20:
                    25:29:04:c6:74:c0:d0:31:cd:8f:31:38:95:16:ba:
                    a8:33:b8:43:f1:b1:1f:c3:30:7f:a2:79:31:13:3d:
                    2d:36:f8:e3:fc:f2:33:6a:b9:39:31:c5:af:c4:8d:
                    0d:1d:64:16:33:aa:fa:84:29:b6:d4:0b:c0:d8:7d:
                    c3:93
                Exponent: 65537 (0x10001)
        X509v3 extensions:
            X509v3 Basic Constraints: critical
                CA:TRUE, pathlen:0
            X509v3 Key Usage: critical
                Digital Signature, Certificate Sign, CRL Sign
            Authority Information Access:
                OCSP - URI:http://isrg.trustid.ocsp.identrust.com
                CA Issuers - URI:http://apps.identrust.com/roots/dstrootcax3.p7c

            X509v3 Authority Key Identifier:
                keyid:C4:A7:B1:A4:7B:2C:71:FA:DB:E1:4B:90:75:FF:C4:15:60:85:89:10

            X509v3 Certificate Policies:
                Policy: 2.23.140.1.2.1
                Policy: 1.3.6.1.4.1.44947.1.1.1
                  CPS: http://cps.root-x1.letsencrypt.org

            X509v3 CRL Distribution Points:

                Full Name:
                  URI:http://crl.identrust.com/DSTROOTCAX3CRL.crl

            X509v3 Subject Key Identifier:
                A8:4A:6A:63:04:7D:DD:BA:E6:D1:39:B7:A6:45:65:EF:F3:A8:EC:A1
    Signature Algorithm: sha256WithRSAEncryption
         dd:33:d7:11:f3:63:58:38:dd:18:15:fb:09:55:be:76:56:b9:
         70:48:a5:69:47:27:7b:c2:24:08:92:f1:5a:1f:4a:12:29:37:
         24:74:51:1c:62:68:b8:cd:95:70:67:e5:f7:a4:bc:4e:28:51:
         cd:9b:e8:ae:87:9d:ea:d8:ba:5a:a1:01:9a:dc:f0:dd:6a:1d:
         6a:d8:3e:57:23:9e:a6:1e:04:62:9a:ff:d7:05:ca:b7:1f:3f:
         c0:0a:48:bc:94:b0:b6:65:62:e0:c1:54:e5:a3:2a:ad:20:c4:
         e9:e6:bb:dc:c8:f6:b5:c3:32:a3:98:cc:77:a8:e6:79:65:07:
         2b:cb:28:fe:3a:16:52:81:ce:52:0c:2e:5f:83:e8:d5:06:33:
         fb:77:6c:ce:40:ea:32:9e:1f:92:5c:41:c1:74:6c:5b:5d:0a:
         5f:33:cc:4d:9f:ac:38:f0:2f:7b:2c:62:9d:d9:a3:91:6f:25:
         1b:2f:90:b1:19:46:3d:f6:7e:1b:a6:7a:87:b9:a3:7a:6d:18:
         fa:25:a5:91:87:15:e0:f2:16:2f:58:b0:06:2f:2c:68:26:c6:
         4b:98:cd:da:9f:0c:f9:7f:90:ed:43:4a:12:44:4e:6f:73:7a:
         28:ea:a4:aa:6e:7b:4c:7d:87:dd:e0:c9:02:44:a7:87:af:c3:
         34:5b:b4:42

@msftgits msftgits transferred this issue from dotnet/corefx Feb 1, 2020
@msftgits msftgits added this to the 3.0 milestone Feb 1, 2020
@ghost ghost locked as resolved and limited conversation to collaborators Dec 14, 2020
@bartonjs bartonjs removed their assignment Jul 26, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
area-System.Security bug os-linux Linux OS (any supported distro) tenet-performance Performance related issue
Projects
None yet
Development

Successfully merging a pull request may close this issue.

7 participants