Strange slowness about crypto.webcrypto.subtle.deriveBits, when called with identical inputs a second time

[fabiospampinato]

Version

22.2.0

Platform

Darwin MBP.local 21.6.0 Darwin Kernel Version 21.6.0: Wed Aug 10 14:28:23 PDT 2022; root:xnu-8020.141.5~2/RELEASE_ARM64_T6000 arm64

Subsystem

No response

What steps will reproduce the bug?

Execute this:

import webcrypto from 'tiny-webcrypto';
import encryptor from 'tiny-encryptor';

const _deriveBits = webcrypto.subtle.deriveBits.bind(webcrypto.subtle);
webcrypto.subtle.deriveBits = async function ( ...args ) {
  // console.log(args);
  console.time('deriveBits');
  const res = await _deriveBits(...args);
  console.timeEnd('deriveBits');
  return res;
};

const SECRET = 'P@ssword!';
const SAMPLE_1GB = new Uint8Array ( 1024 * 1024 * 1024 );
const enc = await encryptor.encrypt ( SAMPLE_1GB, SECRET );
const dec = await encryptor.decrypt ( enc, SECRET );

I see the following output:

~/Desktop/repro ❯ node --version
v22.2.0
~/Desktop/repro ❯ node index.mjs
deriveBits: 1.262ms
deriveBits: 69.418ms
~/Desktop/repro ❯ bun index.mjs
[0.43ms] deriveBits
[0.70ms] deriveBits

I also tried bundling this little repro for the browser and the problem doesn't manifest there either.

Basically through the course of executing that code we end up calling webcrypto.subtle.deriveBits twice, with identical arguments, reported below (but you can log these yourself by uncommenting the console.log in the repro), also asking Node to do very little work to begin with (just one iteration of the derivation function, not a million), and crucially as far as I can see there should be nothing else running concurrently that is blocking the main thread, but still the second execution in this specific scenario is always way slower than the first one, which seems symptomatic of some underlying issue in Node.

[
  {
    name: "PBKDF2",
    salt: Uint8Array(32) [ 242, 78, 191, 112, 241, 109, 103, 131, 247, 218, 234, 20, 139, 106, 24, 50, 87, 41, 33, 23, 250, 89, 1, 228, 230, 71, 135, 106, 133, 145, 86, 63 ],
    iterations: 1,
    hash: {
      name: "SHA-256",
    },
  }, CryptoKey {
    type: "secret",
    extractable: false,
    algorithm: {
      name: "PBKDF2",
    },
    usages: [ "deriveBits" ],
  }, 256
]

I think this is worth a look just because of the wild difference in performance between the two calls, but also since we are dealing with crypto stuff it's probably worth making sure we aren't messing up something important internally.

How often does it reproduce? Is there a required condition?

Always, just execute the code.

What is the expected behavior? Why is that the expected behavior?

The expected behavior is that calling the same function twice takes about the same amount of time basically.

It could be that the GC is triggered during the second call for some reason? But it seems unlikely that if that's the problem it would reproduce pretty much exactly every time, and also ~70ms spent on a GC for what? There are relatively few objects getting allocated here in the first place, at least in userland as far as I can see.

What do you see instead?

I see the second call always taking much longer, which shouldn't be happening.

Additional information

No response