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

Performance loss between jest 25.1.0 and 25.2.7 #9776

Closed
SLKnutson opened this issue Apr 6, 2020 · 22 comments · Fixed by #9873
Closed

Performance loss between jest 25.1.0 and 25.2.7 #9776

SLKnutson opened this issue Apr 6, 2020 · 22 comments · Fixed by #9873

Comments

@SLKnutson
Copy link

💥 Regression Report

We run about 7000 tests total across 630 test files without coverage (see #9457). On my machine, with 25.1.0, the tests took 140 seconds, compared to 350 seconds with 25.2.7. I am running Windows, I believe the effect is less noticeable (but still there) on mac/linux.

Last working version

Worked up to version: 25.1.0

Stopped working in version: somewhere between 25.1.0 and 25.2.7

To Reproduce

Steps to reproduce the behavior: Update from jest 25.1.0 to 25.2.7

Expected behavior

Test run time should not increase drastically when upgrading versions.

Link to repl or repo (highly encouraged)

I don't have a publicly available repo to show, but here are some performance charts I captured. I'm not familiar with the inner workings of Jest, but it appears the performance regression probably has something to do with the resolution of symlinks? We're not using any symlinks as far as I am aware.
25.1.0:
performance_before
25.2.7:
performance_after

Run npx envinfo --preset jest

System:
OS: Windows 10 10.0.14393
CPU: (12) x64 Intel(R) Core(TM) i7-8850H CPU @ 2.60GHz
Binaries:
Node: 12.14.0 - C:\Program Files\nodejs\node.EXE
npm: 6.14.4 - C:\Users*****\AppData\Roaming\npm\npm.CMD
npmPackages:
jest: 25.2.7 => 25.2.7

Thank you for the work that you do maintaining Jest!

@SimenB
Copy link
Member

SimenB commented Apr 6, 2020

We switched from our own resolution algorithm to using resolve, that might be it... It seems to be from what you're showing at least. #9520

A reproduction would help to debug this.

@SimenB
Copy link
Member

SimenB commented Apr 7, 2020

@SLKnutson could you try to comment out the realpath call?

https://github.com/facebook/jest/blob/44a960de28035e7590b21c25de44af5f0f1796df/packages/jest-resolve/src/defaultResolver.ts#L46-L58

Just remove the try-catch.

Another thing that would be great to try would be to cache the realpath call. Something like this:

diff --git i/packages/jest-resolve/src/defaultResolver.ts w/packages/jest-resolve/src/defaultResolver.ts
index 4e990f8b6..0b68a7b42 100644
--- i/packages/jest-resolve/src/defaultResolver.ts
+++ w/packages/jest-resolve/src/defaultResolver.ts
@@ -43,23 +43,14 @@ export default function defaultResolver(
     preserveSymlinks: false,
   });
 
-  try {
-    // Dereference symlinks to ensure we don't create a separate
-    // module instance depending on how it was referenced.
-    const resolved = realpath(result);
-
-    if (resolved) {
-      return resolved;
-    }
-  } catch {
-    // ignore
-  }
-
-  return result;
+  // Dereference symlinks to ensure we don't create a separate
+  // module instance depending on how it was referenced.
+  return realpathCached(result);
 }
 
 export function clearDefaultResolverCache(): void {
   checkedPaths.clear();
+  checkedRealpathPaths.clear();
 }
 
 enum IPathType {
@@ -107,3 +98,29 @@ function isFile(file: Config.Path): boolean {
 function isDirectory(dir: Config.Path): boolean {
   return statSyncCached(dir) === IPathType.DIRECTORY;
 }
+
+const checkedRealpathPaths = new Map<string, string>();
+function realpathCached(path: Config.Path): Config.Path {
+  let result = checkedRealpathPaths.get(path);
+
+  if (result !== undefined) {
+    return result;
+  }
+
+  try {
+    result = realpath(path);
+  } catch {
+    // ignore
+  }
+
+  if (!result) {
+    result = path;
+  }
+
+  checkedRealpathPaths.set(path, result);
+
+  // also cache the result in case it's ever referenced directly - no reason to `realpath` that as well
+  checkedRealpathPaths.set(result, result);
+
+  return result;
+}

If you use patch-package you can apply this patch (patches/jest-resolve+25.2.6.patch):

diff --git a/node_modules/jest-resolve/build/defaultResolver.js b/node_modules/jest-resolve/build/defaultResolver.js
index 61d1341..20a4590 100644
--- a/node_modules/jest-resolve/build/defaultResolver.js
+++ b/node_modules/jest-resolve/build/defaultResolver.js
@@ -123,25 +123,15 @@ function defaultResolver(path, options) {
     moduleDirectory: options.moduleDirectory,
     paths: options.paths,
     preserveSymlinks: false
-  });
+  }); // Dereference symlinks to ensure we don't create a separate
+  // module instance depending on how it was referenced.
 
-  try {
-    // Dereference symlinks to ensure we don't create a separate
-    // module instance depending on how it was referenced.
-    const resolved = (0, _realpathNative().sync)(result);
-
-    if (resolved) {
-      return resolved;
-    }
-  } catch (_unused) {
-    // ignore
-  }
-
-  return result;
+  return realpathCached(result);
 }
 
 function clearDefaultResolverCache() {
   checkedPaths.clear();
+  checkedRealpathPaths.clear();
 }
 
 var IPathType;
@@ -195,3 +185,28 @@ function isFile(file) {
 function isDirectory(dir) {
   return statSyncCached(dir) === IPathType.DIRECTORY;
 }
+
+const checkedRealpathPaths = new Map();
+
+function realpathCached(path) {
+  let result = checkedRealpathPaths.get(path);
+
+  if (result !== undefined) {
+    return result;
+  }
+
+  try {
+    result = (0, _realpathNative().sync)(path);
+  } catch (_unused) {
+    // ignore
+  }
+
+  if (!result) {
+    result = path;
+  }
+
+  checkedRealpathPaths.set(path, result); // also cache the result in case it's ever referenced directly - no reason to `realpath` that as well
+
+  checkedRealpathPaths.set(result, result);
+  return result;
+}

@SLKnutson
Copy link
Author

Without realpath call: ~320 seconds
With cached realpath call: ~330 seconds

I also tried without the realpath call and setting "preserveSymlinks=true" in the resolve call. With that, I got ~105 seconds. That disables the call to fs.realpathSync in sync.js. We could be running into this issue nodejs/node-v0.x-archive#7902

@SimenB
Copy link
Member

SimenB commented Apr 7, 2020

Cool, thanks for testing! Too bad it made no real difference 😅 What happens if we keep the realpath call in Jest but pass preserveSymlinks: true to resolve? Seems we should do that anyways since we resolve the path on our side.

Our realpath call uses fs.realpathSync.native under the hood, which possibly doesn't have the perf issue referred to in that issue?

https://nodejs.org/api/fs.html#fs_fs_realpathsync_native_path_options

If perf is still horrible, I think we might need to roll it back and introduce some sort of resolveSymlinks option as part of a larger symlink support (#7364, #7549, #9351, etc)...

(on my machine I see no difference between any of the discussed options, so it's hard for me to test this, unfortunately)

@SLKnutson
Copy link
Author

With preserveSymlinks: true and the realpath call enabled it runs at ~120 seconds. That seems like a good easy win.

@SimenB
Copy link
Member

SimenB commented Apr 7, 2020

Ah, wonderful! I think that's safe, wanna send a PR?


@ljharb this might be interesting to you. Using fs.realpathSync.native (or process.binding('fs').realpath on older versions of node) seems to have quite large performance implications, at least on Windows

@ljharb
Copy link
Contributor

ljharb commented Apr 7, 2020

@SimenB thanks for the ping; i'd generally try to avoid using process.binding or non-JS code, since the UX of it is rarely worth the perf. resolve doesn't, afaik, use either of those approaches.

@SimenB
Copy link
Member

SimenB commented Apr 7, 2020

resolve does fs.realpath(Sync) if passed preserveSymlinks: false. Swapping that out with the native realpath seems to take the test suite discussed in the OP from 350 seconds to 120 seconds.

@SLKnutson if you could test swapping out
https://github.com/browserify/resolve/blob/edfe3f76242afc5caf7573ab6635321e7c5126ba/lib/sync.js#L31

with fs.realpathSync.native (and passing preserveSymlinks: false plus removing the realpath call in Jest) that'd be great to test the theory. There's multiple realpath calls in there though, so impact is probably not as large as a single final realpath after resolution is done

@ljharb
Copy link
Contributor

ljharb commented Apr 7, 2020

Ah, I misunderstood; you're saying using the native one is better. In that case, I'd be fine conditionally invoking it in resolve when it's present; want to make a PR? :-)

@SimenB
Copy link
Member

SimenB commented Apr 7, 2020

Right, I can see my comment was a bit ambiguous, sorry about that.

I can open a PR, sure 👍 If nothing else it would be good to run resolve's extensive unit tests against it to see if it's actually a drop-in replacement or not

@SimenB
Copy link
Member

SimenB commented Apr 7, 2020

browserify/resolve#217

@SLKnutson
Copy link
Author

@SimenB When running using fs.realpathSync.native in sync.js and without the _realpathNative().sync call in jest-resolve, the tests take ~215 seconds to run.

I can create a PR if you would like, but I would prefer not to because I don't have jest forked and setup on my computer.

@SimenB
Copy link
Member

SimenB commented Apr 8, 2020

@SLKnutson right, thanks! on closer thought I don't think it's correct in Jest - we want to resolve the symlink on every directory we lookup, not just the final path. Making the change I suggested leads to a failing unit test, which exposes the bug it introduces.

Using native realpath has landed in resolve now - I think when browserify/resolve#218 also lands we can use that option to plug in a cached version. I'm hoping that will bring the numbers back down to the levels they were for 25.1.0. If not we might have to look at Jest's old implementation (https://github.com/facebook/jest/blob/v25.1.0/packages/jest-resolve/src/defaultResolver.ts) and try to figure out if we can optimize resolve somehow.

Thanks for testing this for us @SLKnutson, I'll ping again if and when it's ready to test again!

@SimenB
Copy link
Member

SimenB commented Apr 22, 2020

@SLKnutson you should be able to install resolve@1.16.1 now which internally uses fs.realpathSync.native if available, i.e. the last thing you tested. It's a start at least 🙂 When we get browserify/resolve#218 in we can try to cache the calls. I'll update in jest so the next version should force the newer resolve, but in the meantime you can upgrade in your own project

You might also be interested in #9732 which would allow us to effectively set preserveSymlinks: true, which gave the best effect for you

@SLKnutson
Copy link
Author

Thanks @SimenB. I tried out the same code I was testing before with jest 25.2.7 installed and resolve 1.16.1 and saw runs of ~215 seconds. I also got similar results with jest 25.4.0 and resolve 1.16.1. Good work!

@SimenB
Copy link
Member

SimenB commented Apr 23, 2020

That's great, thanks for testing! Still some ways of the 140 sec you saw with 25.1.0, though. Could you try updating to resolve@1.17.0 and using the cached version from #9873?

Built version:

'use strict';

Object.defineProperty(exports, '__esModule', {
  value: true
});
exports.default = defaultResolver;
exports.clearDefaultResolverCache = clearDefaultResolverCache;

function fs() {
  const data = _interopRequireWildcard(require('fs'));

  fs = function () {
    return data;
  };

  return data;
}

function _resolve() {
  const data = require('resolve');

  _resolve = function () {
    return data;
  };

  return data;
}

function _browserResolve() {
  const data = require('browser-resolve');

  _browserResolve = function () {
    return data;
  };

  return data;
}

function _realpathNative() {
  const data = require('realpath-native');

  _realpathNative = function () {
    return data;
  };

  return data;
}

function _jestPnpResolver() {
  const data = _interopRequireDefault(require('jest-pnp-resolver'));

  _jestPnpResolver = function () {
    return data;
  };

  return data;
}

function _interopRequireDefault(obj) {
  return obj && obj.__esModule ? obj : {default: obj};
}

function _getRequireWildcardCache() {
  if (typeof WeakMap !== 'function') return null;
  var cache = new WeakMap();
  _getRequireWildcardCache = function () {
    return cache;
  };
  return cache;
}

function _interopRequireWildcard(obj) {
  if (obj && obj.__esModule) {
    return obj;
  }
  if (obj === null || (typeof obj !== 'object' && typeof obj !== 'function')) {
    return {default: obj};
  }
  var cache = _getRequireWildcardCache();
  if (cache && cache.has(obj)) {
    return cache.get(obj);
  }
  var newObj = {};
  var hasPropertyDescriptor =
    Object.defineProperty && Object.getOwnPropertyDescriptor;
  for (var key in obj) {
    if (Object.prototype.hasOwnProperty.call(obj, key)) {
      var desc = hasPropertyDescriptor
        ? Object.getOwnPropertyDescriptor(obj, key)
        : null;
      if (desc && (desc.get || desc.set)) {
        Object.defineProperty(newObj, key, desc);
      } else {
        newObj[key] = obj[key];
      }
    }
  }
  newObj.default = obj;
  if (cache) {
    cache.set(obj, newObj);
  }
  return newObj;
}

/**
 * Copyright (c) Facebook, Inc. and its affiliates. All Rights Reserved.
 *
 * This source code is licensed under the MIT license found in the
 * LICENSE file in the root directory of this source tree.
 */
function defaultResolver(path, options) {
  // @ts-ignore: the "pnp" version named isn't in DefinitelyTyped
  if (process.versions.pnp) {
    return (0, _jestPnpResolver().default)(path, options);
  }

  const resolve = options.browser ? _browserResolve().sync : _resolve().sync;
  const result = resolve(path, {
    basedir: options.basedir,
    extensions: options.extensions,
    isDirectory,
    isFile,
    moduleDirectory: options.moduleDirectory,
    paths: options.paths,
    preserveSymlinks: false,
    // @ts-ignore: https://github.com/DefinitelyTyped/DefinitelyTyped/pull/44137
    realpathSync
  }); // Dereference symlinks to ensure we don't create a separate
  // module instance depending on how it was referenced.

  return realpathSync(result);
}

function clearDefaultResolverCache() {
  checkedPaths.clear();
  checkedRealpathPaths.clear();
}

var IPathType;

(function (IPathType) {
  IPathType[(IPathType['FILE'] = 1)] = 'FILE';
  IPathType[(IPathType['DIRECTORY'] = 2)] = 'DIRECTORY';
  IPathType[(IPathType['OTHER'] = 3)] = 'OTHER';
})(IPathType || (IPathType = {}));

const checkedPaths = new Map();

function statSyncCached(path) {
  const result = checkedPaths.get(path);

  if (result !== undefined) {
    return result;
  }

  let stat;

  try {
    stat = fs().statSync(path);
  } catch (e) {
    if (!(e && (e.code === 'ENOENT' || e.code === 'ENOTDIR'))) {
      throw e;
    }
  }

  if (stat) {
    if (stat.isFile() || stat.isFIFO()) {
      checkedPaths.set(path, IPathType.FILE);
      return IPathType.FILE;
    } else if (stat.isDirectory()) {
      checkedPaths.set(path, IPathType.DIRECTORY);
      return IPathType.DIRECTORY;
    }
  }

  checkedPaths.set(path, IPathType.OTHER);
  return IPathType.OTHER;
}

const checkedRealpathPaths = new Map();

function realpathCached(path) {
  let result = checkedRealpathPaths.get(path);

  if (result !== undefined) {
    return result;
  }

  try {
    result = (0, _realpathNative().sync)(path);
  } catch (error) {
    if (error.code !== 'ENOENT') {
      throw error;
    }
  }

  if (!result) {
    result = path;
  }

  checkedRealpathPaths.set(path, result);

  if (path !== result) {
    // also cache the result in case it's ever referenced directly - no reason to `realpath` that as well
    checkedRealpathPaths.set(result, result);
  }

  return result;
}
/*
 * helper functions
 */

function isFile(file) {
  return statSyncCached(file) === IPathType.FILE;
}

function isDirectory(dir) {
  return statSyncCached(dir) === IPathType.DIRECTORY;
}

function realpathSync(file) {
  return realpathCached(file);
}

@SLKnutson
Copy link
Author

With those changes, on the latest version of jest (25.4.0), I had test runs of about 115 seconds. That's the fastest I've seen our tests run in a long time.

@SimenB
Copy link
Member

SimenB commented Apr 23, 2020

Ah, wonderful! Thanks so much for your help digging into this

@sibelius
Copy link

any plans for a new release?

@SimenB
Copy link
Member

SimenB commented Apr 27, 2020

Wanna land #9443 and #9806 first

@SimenB
Copy link
Member

SimenB commented Apr 28, 2020

25.5 is out

@github-actions
Copy link

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.
Please note this issue tracker is not a help forum. We recommend using StackOverflow or our discord channel for questions.

@github-actions github-actions bot locked as resolved and limited conversation to collaborators May 11, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants