Metro: Metro 0.45 / RN 0.57.0 - Initial builds 5-10x slower

[mjmasn]

Do you want to request a feature or report a bug?
Bug (ported from RN repo as the issue reported by @Winglonelion was closed and locked there - https://github.com/facebook/react-native/issues/21138)

What is the current behavior?
First build of react-native project takes ~3 mins (i.e. after running yarn start then react-native run-android). Subsequent builds via Dev Menu -> Reload seem fine although maybe slower speed is less noticeable for incremental builds.

If the current behavior is a bug, please provide the steps to reproduce and a minimal repository on GitHub that we can yarn install and yarn test.
It's probably not so noticable with small projects so bit hard to do a repro as our production app is not open-source. But building any project with RN 0.56.1 and then 0.57.0 should show a difference.

What is the expected behavior?
It used to take maybe ~30s at most for a reasonably sized project. I hardly used to notice the short wait.

Please provide your exact Metro configuration and mention your Metro, node, yarn/npm version and operating system.

[email protected]

  React Native Environment Info:
    System:
      OS: Linux 4.15 Ubuntu 16.04.5 LTS (Xenial Xerus)
      CPU: x64 Intel(R) Core(TM) i7-7700 CPU @ 3.60GHz
      Memory: 753.61 MB / 15.54 GB
      Shell: 4.3.48 - /bin/bash
    Binaries:
      Node: 8.11.0 - ~/.nvm/versions/node/v8.11.0/bin/node
      Yarn: 1.9.4 - /usr/bin/yarn
      npm: 5.6.0 - ~/.nvm/versions/node/v8.11.0/bin/npm
      Watchman: 4.9.0 - /usr/local/bin/watchman
    SDKs:
      Android SDK:
        Build Tools: 23.0.1, 26.0.1, 26.0.2, 26.0.3, 27.0.0, 27.0.3
        API Levels: 16, 19, 22, 23, 26, 27, 28
    IDEs:
      Android Studio: 3.1 AI-173.4907809
    npmPackages:
      react: ^16.5.0 => 16.5.1 
      react-native: 0.57.0 => 0.57.0 
    npmGlobalPackages:
      create-react-native-app: 1.0.0
      react-native-cli: 2.0.1
      react-native-git-upgrade: 0.2.7



md5-5f9c117c350e5528e792177106ab9f61



adb_all reverse tcp:3000 tcp:3000
# adb_all reverse ...
react-native run-android --appIdSuffix=debug

Where adb_all is a function that loops through all connected devices / emulators and runs an adb command, in this case to reverse proxy our locally running services to the device.

The differences between our scripts and yarn start + react-native run-android for the purposes of this bug report should be pretty minimal though.

[rafeca]

Thanks for reporting the issue! A couple of questions:

1- Does this happen also when the local cache is full? e.g is the first build fast after restarting Metro?
2- Have you noticed any slowness when building the release builds? I'm asking because we've added some smarter optimizations to reduce bundle size on production builds which can increase build times, but these should not affect development.

[mjmasn]

@rafeca thanks for the reply :)

1) It's quick if run again without --reset-cache or if just reloading from the dev menu which I guess is expected. I could be imagining it, but did I read something like the --reset-cache option wasn't being passed down to other tools in the build chain and now that's fixed? Can't find that comment anywhere now though :thinking:

For debug builds we run node node_modules/react-native/local-cli/cli.js start --reset-cache and for release builds I added the --reset-cache option into our custom react.gradle file. The reason being the insane amount of issues related to bad caching since getting into RN dev at the start of the year. Hasn't happened recently but there have been times we've run watchman watch-del-all, deleted /tmp/react-* /tmp/metro-* /tmp/haste-* etc. deleted android/build/, android/app/build/, and even deleted the cache in ~/.gradle, done a full reboot of the machine, then the next build still has the wrong bundle file in it somehow :scream:

So if it is down to --reset-cache working properly now then I'll happily take the slower builds :grinning:

2) Our release builds (for android) do vary a bit but I remember it being about 2m 20s for a release build with RN 0.56, and I just did a build with RN 0.57 which took 3m 30s (vs ~3m for just the bundle in dev mode). That's not a huge problem, especially if it reduces bundle size, and I tend to fire off a set of builds and go do something else for 10-15 minutes.

We're only releasing on android with this app at the moment but in the process of exploring migrating from an existing native app for iOS. For RN 0.56 iOS apparently it takes 20+ minutes for a release archive. Not sure about 0.57 yet, should be able to confirm sometime this week, but I think most of that extra time is building the native side anyway.

[mjmasn]

@rafeca and in case it matters, the rough timings are like this in dev mode. Super slow start with a sudden burst in the last 10s. Previously it was a constant velocity 0-100% over about 20/30s.

  0s BUNDLE  [android, dev] ./index.js ░░░░░░░░░░░░░░░░ 0.0% (0/12)
 30s BUNDLE  [android, dev] ./index.js ▓░░░░░░░░░░░░░░░ 9.8% (165/528)
 60s BUNDLE  [android, dev] ./index.js ▓▓░░░░░░░░░░░░░░ 17.4% (229/3405)
 90s BUNDLE  [android, dev] ./index.js ▓▓░░░░░░░░░░░░░░ 17.4% (661/3789)
120s BUNDLE  [android, dev] ./index.js ▓▓░░░░░░░░░░░░░░ 17.4% (1091/4232)
150s BUNDLE  [android, dev] ./index.js ▓▓░░░░░░░░░░░░░░ 17.4% (1499/4344)
180s BUNDLE  [android, dev] ./index.js ▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓ 100.0% (4349/4349), done.

[rafeca]

Thanks for the detailed information!

During startup Metro prints a message saying:

Loading dependency graph...

Once the dependency map gets initialized, the message becomes:

Loading dependency graph, done.

Can you check if the slowness is caused by the depdency graph loading? (this is the initialization of jest-haste-map)

[rafeca]

Also, regarding the cache issues that you mention, these are usually caused by external files that affect the transformation output (like .babelrc or babel.config.js files). Since metro does not know about them, even if you change them and restart metro/etc the cache won't get invalidated.

In order to fix that, Metro has a config param called cacheVersion (more info).

You can set it to any string and the whole transform cache of metro will get invalidated once this string changes.

So, in order to use this to invalidate the cache once some files change in your repo change you can do something like:

const crypto = require('crypto');

function getFileHash(file) {
  return crypto
    .createHash('sha1')
    .update(fs.readFileSync(file))
    .digest('hex');
}

const cacheKeyParts = [
  './package.json',
  './yarn.lock',
  './.babelrc',
  /* ... */
].map(file => getFileHash(require.resolve(file)));

const cacheVersion = crypto
    .createHash('sha1')
    .update(cacheKeyParts.join('$'))
    .digest('hex');

This will improve the developer experience quite a lot if your app is big, since transforming the whole app from scratch every time is painful. On production, I guess that is fine to keep the --reset-cache for safety.

[mjmasn]

@rafeca Loading dependency graph... -> Loading dependency graph, done. takes ~5s. I had noticed it occasionally taking a lot longer, say ~20 - 30s in RN 0.56 but haven't noticed any issues with 0.57.

Ahhh OK, thanks for that info, interesting as another part of my 'solution' for production builds was to write to a file version.json from gradle whenever the build number incremented. Then imported the json file to JS code and showed an alert if there was a mismatch with the version returned by native code. After implementing that I didn't actually get any mismatch alerts in production builds so I assumed it must have been enough that the version.json file changing invalidated some cache somewhere. cacheVersion sounds like the ideal solution for dev mode though, perhaps I should have RTFM but I just assumed RNs default setup would be good enough...

One more piece of info - our .babelrc which is pretty straightforward. Not sure why we're resolving core-util-is to core-util-is, and can't remember what we're using legacy decorators spec for, so this could maybe be simplified further.

{
  "presets": ["module:metro-react-native-babel-preset"],
  "plugins": [
    ["@babel/plugin-proposal-decorators", {"legacy": true}],
    [
      "module-resolver",
      {
        "alias": {
          "crypto": "crypto-js",
          "stream": "readable-stream",
          "core-util-is": "core-util-is"
        }
      }
    ]
  ]
}

[rafeca]

Ok, now we know that the slowdown comes from the transformation of files.

Can you check if there may be any specific file that could be taking a long time to transform?

You can do something like the following to hook into the Metro logger to print on the console the time that it takes to transform each file:

const Metro = require('metro');

Metro.Logger.on('log', logEntry => {
    if (
      logEntry.action_name === 'Transforming file' &&
      logEntry.action_phase === 'end'
    ) {
      console.log(logEntry.file_name, logEntry.duration_ms);
    }
  });

You can add this logic in your rn-cli.config.js file.

[Winglonelion]

Thanks @mjmasn alot for reported it in here. I has some deadline yesterday, so i couldn't check regularity notifications.

Exactly like describle of mjmasn. The first bundling progress and after reset-cache made Metro x5 - x10 slower. And it common stucked in starting of bundling progress. It maybe the progress of transform assets.

My Project using some large Realm file with total size about 100 MB. But it can load fine in older Metro

[mjmasn]

@rafeca ok so in terms of timings:

Type | Total Files | Average ms
:---|:---|:---
node_modules | 1348 | 10907
assets (mostly png images) | 2692 | 110241
other (our code) | 319 | 18034

Seems like images are taking ages, all are at least 50000ms and the highest is 143782ms. Not really sure why, isn't this basically just a hashing step given the images aren't included in the JS bundle?

[rafeca]

Are these times average per file? 😟 That's not expected at all... Usually transforming a file should take much less than a second...

Do you have a custom .babelrc config file? which plugins are you using?

[mjmasn]

@rafeca yeah per file :scream_cat:

I've just created some test repos which show the issue one two brand new projects created with react-native init:

https://github.com/mjmasn/FastMetro
https://github.com/mjmasn/SlowMetro

I pasted the timing logs from my machine in the READMEs to save you having to run them.

As mentioned in the SlowMetro README, node_modules/react-native/Libraries/Modal/Modal.js is unchanged between the two RN versions yet takes 60ms to transform with RN 0.56.1 (Metro 0.38.4), and 3658ms to transform with RN 0.57.0 (Metro 0.45.3).

Our actual .babelrc is the following, but removing everything except the metro preset didn't improve things:

{
  "presets": ["module:metro-react-native-babel-preset"],
  "plugins": [
    ["@babel/plugin-proposal-decorators", {"legacy": true}],
    [
      "module-resolver",
      {
        "alias": {
          "crypto": "crypto-js",
          "stream": "readable-stream",
          "core-util-is": "core-util-is"
        }
      }
    ]
  ]
}

[rafeca]

wow, thanks a lot! these repro steps are really useful and I've been in fact able to reproduce the issue now.

I was trying to repro using yarn react-native bundle --entry-file index.js --platform android --bundle-output ./tmp.js --reset-cache, which should be calling the transformer the same way, but somehow it isn't.

Investigating atm 🕵️‍♂️

[rafeca]

Ok! found it! 😅

Somehow, when running the development server, the React Native CLI is not configuring Metro to use multiple workers to parallelize the transformation of files across CPUs.

This is why build times is ~5-10X slower (depending on your number of cpus).

I'm going to send a fix and release a patch version of Metro

[rafeca]

Until we have a fix you can workaround the issue by adding the --max-workers param to the CLI command, eg:

$ node node_modules/react-native/local-cli/cli.js start --reset-cache --max-workers=6

[mjmasn]

@rafeca ah no way! I had actually noticed my PC was running really quiet (smallish form factor with super noisy fan makes it very noticeable when it's working hard) My colleagues have probably been enjoying the break from it :joy:

Thank you for spending time looking into this one, much appreciated :)

Edit: Yeah looks good:

[Winglonelion]

Perfectly. You made my day