[Bug] Bad performance

[sylbru]

Describe the bug

Even with no dependencies and no files in my directory, a very simple command defined in scripts takes almost a second to execute. Not sure if this counts as a bug, but one of the sellings points of yarn used to be that it was fast…

I can understand Yarn needs more time to boot than before, but this seems like a lot, especially when using it to run simple external commands or even a simple yarn -v.

To Reproduce

In an empty directory:

• create a package.json with the following:

  {
    "scripts": {
      "test": "cal"
    }
  }
  

• yarn set version berry
• yarn install
• time yarn test gives:

  ...    
                        
  real    0m0,687s
  user    0m0,907s
  sys 0m0,144s
  

  while time cal gives:

  ...                  
  
  real    0m0,003s
  user    0m0,002s
  sys 0m0,001s
  

Environment:

• Linux Mint 20.1
• Node 15.5
• Yarn 2.4.1

[sylbru]

In a real project, my (very small) unit test suite takes 0.12s when started directly from phpunit, 3.19s when started via yarn. What is happening there?

[arcanis]

a very simple command defined in scripts takes almost a second to execute

It doesn't - the time you should read is real (time from pressing enter to the result), not user (cpu time), so the actual run time is ~400ms. This result isn't entirely unexpected, considering that yarn run has various overheads compared to just running a command in your shell:

0. Running yarn goes to the global Yarn, which shells out to the local one
1. Then you have Node itself, which needs to parse the file and execute it
2. Then you have Yarn which finds your configuration file, reads it, loads the project data
3. Scripts get executed in a special environment (with bins in the PATH), which needs to be prepared
4. Then the script gets executed; in Yarn 2, we use a portable shell (in JS), which adds a slight overhead

In a real project, my (very small) unit test suite takes 0.12s when started directly from phpunit, 3.19s when started via yarn. What is happening there?

It's a good thing you mentioned that in particular - I noticed that in one of our functions, we repeatedly require the same file, one extra time for each dependency that exposes bin entries. The more you have, the slower the env preparation (step 3 I mentioned) becomes (hence why you noticed considerably slower startup than in an empty project).

I'll look to improve that.

[sylbru]

@arcanis Thanks for pointing out the difference between the values returned by time. I did think it felt a little bit faster than "almost a second" but I didn’t think long enough :)

I appreciate the details about what actually happens when we yarn run some command. It seems like there’s a clear difference between yarn 1 and yarn 2, so that’s probably because of the problem you noticed. The PR seems to improve that quite a bit. I can’t wait to try it, thanks!

[merceyz]

I can’t wait to try it, thanks!

You can try it right now by running

yarn set version from sources --branch 2564

[sylbru]

Execution time reduced by 50% when running my unit test suite!