crypto.getDiffieHellman() much slower after OpenSSL 1.1.1c update

[Trott]

• Version: master branch (v13.0.0-pre)
• Platform: macOS Mojave but I've seen it on Linux in CI too
• Subsystem: crypto

node compiled from the master branch takes 24 seconds while Node.js 12.4.0 takes less than 2 seconds.

$ time ./node -e "require('crypto').getDiffieHellman('modp18')" 

real	0m24.159s
user	0m23.687s
sys	0m0.066s
$ time node -e "require('crypto').getDiffieHellman('modp18')"

real	0m1.403s
user	0m1.173s
sys	0m0.070s
$

@bnoordhuis notes that the default key size in 1.1.1c was increased from 1024 bits to 2048 bits, but IIUC, specifying modp18 sets the key size for both to a large value.

Bug? Ot maybe it's not-a-bug because it's using a more reliable source of randomness so things are slower or something like that?

@nodejs/crypto

[addaleax]

Fwiw, the commit that changed behaviour seems to be openssl/openssl@2500c09.

[addaleax]

And assuming that this is intentional – as that commit message hints at – it might make sense to provide an asynchronous function that offloads to the threadpool for creating these objects.

[Trott]

And assuming that this is intentional – as that commit message hints at – it might make sense to provide an asynchronous function that offloads to the threadpool for creating these objects.

Yeah, it does seem as though that commit message indicates that a lot more work is now done to create DH objects and that this is by design. Close this as "not a bug"?

[bnoordhuis]

Yes, the commit that Anna linked to is the culprit. Before, it did 3-5 primality checks, depending on the key size; now it always does 64. That's a lot of big integer arithmetic and reading from /dev/urandom.

A new asynchronous API seems like the best way forward.

[alexey-temnikov]

I think it is causing now my CPU to go crazy 100% on node 12.8.0

 [Summary]:
   ticks  total  nonlib   name
     16    0.0%    0.0%  JavaScript
  95718   99.9%  100.0%  C++
    143    0.1%    0.1%  GC
     63    0.1%          Shared libraries
      4    0.0%          Unaccounted

 ticks parent  name
  92138   96.2%  T node::crypto::DiffieHellman::New(v8::FunctionCallbackInfo<v8::Value> const&)
  92138  100.0%    t __ZN2v88internal12_GLOBAL__N_125SimpleInstallGetterSetterEPNS0_7IsolateENS0_6HandleINS0_8JSObjectEEENS4_INS0_6StringEEENS0_8Builtins4NameESA_
  92138  100.0%      LazyCompile: ~DiffieHellman internal/crypto/diffiehellman.js:32:23
  92138  100.0%        LazyCompile: ~createDiffieHellman crypto.js:126:29

[apricote]

An application responsible for SFTP connections was timing out on new connections for us after we updated to Node 10.16.2.

While the connection is being created the event loop is blocked for 200ms on my laptop.

To isolate the issue I created a small script that opened the connection and immediatly closed it again. Here are my results for different Nodejs Versions (Node 10 and Node 12, each directly before and after the update to OpenSSL 1.1.1c):

Node 10

Node 10.16.0

 [Summary]:
   ticks  total  nonlib   name
     32    5.9%   23.9%  JavaScript
     99   18.1%   73.9%  C++
      7    1.3%    5.2%  GC
    412   75.5%          Shared libraries
      3    0.5%          Unaccounted

   ticks parent  name
    347   63.6%  /usr/local/bin/node
    339   97.7%    node::IsolateData::IsolateData(v8::Isolate*, uv_loop_s*, node::MultiIsolatePlatform*, unsigned int*)
    160   47.2%      LazyCompile: ~DiffieHellman internal/crypto/diffiehellman.js:29:23
    160  100.0%        LazyCompile: ~createDiffieHellman crypto.js:120:29
    160  100.0%          LazyCompile: ~onKEXDH_GEX_GROUP /app/node_modules/ssh2-streams/lib/ssh.js:2567:27
    160  100.0%            LazyCompile: ~<anonymous> /app/node_modules/ssh2-streams/lib/ssh.js:217:21

10.16.1

 [Summary]:
   ticks  total  nonlib   name
     28    0.9%   24.1%  JavaScript
     85    2.8%   73.3%  C++
      7    0.2%    6.0%  GC
   2912   96.2%          Shared libraries
      3    0.1%          Unaccounted

   ticks parent  name
   2854   94.3%  /usr/local/bin/node
   2842   99.6%    node::IsolateData::IsolateData(v8::Isolate*, uv_loop_s*, node::MultiIsolatePlatform*, unsigned int*)
   2703   95.1%      LazyCompile: ~DiffieHellman internal/crypto/diffiehellman.js:29:23
   2703  100.0%        LazyCompile: ~createDiffieHellman crypto.js:120:29
   2703  100.0%          LazyCompile: ~onKEXDH_GEX_GROUP /app/node_modules/ssh2-streams/lib/ssh.js:2567:27
   2703  100.0%            LazyCompile: ~<anonymous> /app/node_modules/ssh2-streams/lib/ssh.js:217:21

Node 12

12.4.0

 [Summary]:
   ticks  total  nonlib   name
      0    0.0%    0.0%  JavaScript
    127   24.5%  100.0%  C++
      4    0.8%    3.1%  GC
    392   75.5%          Shared libraries

   ticks parent  name
    353   68.0%  /usr/local/bin/node
    340   96.3%    node::Environment::PrintSyncTrace() const
    179   52.6%      LazyCompile: ~DiffieHellman internal/crypto/diffiehellman.js:32:23
    179  100.0%        LazyCompile: ~createDiffieHellman crypto.js:126:29
    179  100.0%          LazyCompile: ~onKEXDH_GEX_GROUP /app/node_modules/ssh2-streams/lib/ssh.js:2567:27
    179  100.0%            LazyCompile: ~<anonymous> /app/node_modules/ssh2-streams/lib/ssh.js:217:21

12.5.0

 [Summary]:
   ticks  total  nonlib   name
      0    0.0%    0.0%  JavaScript
    125    3.6%  100.0%  C++
      5    0.1%    4.0%  GC
   3331   96.4%          Shared libraries

   ticks parent  name
   3290   95.2%  /usr/local/bin/node
   3281   99.7%    node::cares_wrap::(anonymous namespace)::Initialize(v8::Local<v8::Object>, v8::Local<v8::Value>, v8::Local<v8::Context>)
   3135   95.6%      LazyCompile: ~DiffieHellman internal/crypto/diffiehellman.js:32:23
   3135  100.0%        LazyCompile: ~createDiffieHellman crypto.js:126:29
   3135  100.0%          LazyCompile: ~onKEXDH_GEX_GROUP /app/node_modules/ssh2-streams/lib/ssh.js:2567:27
   3135  100.0%            LazyCompile: ~<anonymous> /app/node_modules/ssh2-streams/lib/ssh.js:217:21