[Bug?]: Terminal output makes yarn install very slow

[blimmer]

Self-service

• I'd be willing to implement a fix

Describe the bug

When running a yarn install with my sample repository (https://github.com/blimmer/yarn-bug-reports/tree/output-buffering), I experience three very different timings to complete a yarn install on the same repository.

It appears that this has something to do with how quickly my terminal can display the scrolling output coming from the yarn invocation.

To reproduce

I'm sorry, but I wasn't able to get this working in Sherlock. However, it should be pretty simple to pull down my test repository to see this behavior.

1. git clone -b output-buffering https://github.com/blimmer/yarn-bug-reports.git
2. cd yarn-bug-reports

Now we will go through three distinct scenarios, using time to calculate the time each process takes to complete the same command.

With Terminal Focused

In the terminal, run time yarn install. Leave the terminal focused. You'll notice a lot of warnings (e.g., ➤ YN0013: │ jest-runtime@npm:27.5.1 can't be found in the cache and will be fetched from the remote regis) scrolling by since it's the first time running yarn install in this repo.

For me, this takes 2 minutes 15 seconds yarn install 102.45s user 9.16s system 82% cpu 2:15.24 total.

Logs

   ~/code/yarn-bug-reports   output-buffering  time yarn install
  ➤ YN0000: ┌ Resolution step
  ➤ YN0002: │ @endemolshinegroup/cosmiconfig-typescript-loader@npm:3.0.2 [9a4a3] doesn't provide typescript (pe9669), requested by ts-node
  ➤ YN0002: │ @endemolshinegroup/cosmiconfig-typescript-loader@npm:3.0.2 [c6211] doesn't provide typescript (pc78ba), requested by ts-node
  ➤ YN0002: │ infrastructure@workspace:infrastructure doesn't provide @aws-cdk/aws-logs (p0d64c), requested by datadog-cdk-constructs
  ➤ YN0002: │ infrastructure@workspace:infrastructure doesn't provide @aws-cdk/aws-logs-destinations (p52934), requested by datadog-cdk-constructs
  ➤ YN0002: │ infrastructure@workspace:infrastructure doesn't provide constructs (pdcaf4), requested by datadog-cdk-constructs
  ➤ YN0002: │ infrastructure@workspace:infrastructure doesn't provide jest (pf1db5), requested by @aws-cdk/assert
  ➤ YN0002: │ infrastructure@workspace:infrastructure doesn't provide prettier (pb5d06), requested by eslint-plugin-prettier
  ➤ YN0002: │ yarn-repro@workspace:. doesn't provide graphql-tag (p503cc), requested by @graphql-codegen/typescript-react-apollo
  ➤ YN0000: │ Some peer dependencies are incorrectly met; run yarn explain peer-requirements <hash> for details, where <hash> is the six-letter p-prefixed code
  ➤ YN0000: └ Completed
  ➤ YN0000: ┌ Fetch step
  ➤ YN0013: │ yargs@npm:16.2.0 can't be found in the cache and will be fetched from the remote registry
  ➤ YN0013: │ yargs@npm:17.3.1 can't be found in the cache and will be fetched from the remote registry
  ➤ YN0013: │ yn@npm:3.1.1 can't be found in the cache and will be fetched from the remote registry
  ➤ YN0013: │ yocto-queue@npm:0.1.0 can't be found in the cache and will be fetched from the remote registr
  ➤ YN0013: │ zip-stream@npm:4.1.0 can't be found in the cache and will be fetched from the remote registry
  ➤ YN0000: └ Completed in 2m 10s
  ➤ YN0000: ┌ Link step
  ➤ YN0007: │ esbuild@npm:0.14.23 must be built because it never has been before or the last one failed
  ➤ YN0007: │ esbuild@npm:0.12.29 must be built because it never has been before or the last one failed
  ➤ YN0000: └ Completed in 4s 929ms
  ➤ YN0000: Done with warnings in 2m 15s
  yarn install  102.45s user 9.16s system 82% cpu 2:15.24 total

IMPORTANT: reset state between tests by running:
git clean -fdx && yarn cache clean --all

With Terminal Unfocused

I just happened to notice that when another ITerm window is focused, the logs scroll by much more quickly.

First, split your pane horizontally by right-clicking and choosing "Split Pane Horizontally". Then, run time yarn install in one pane, and immediately click into the new blank pane you opened. You'll notice that the log output scrolls much more quickly when the window that time yarn install is running in is not actively selected.

This video shows what I'm experiencing on my machine: https://www.youtube.com/watch?v=xCfglVxuD7g.

This takes way less time to run yarn install than the previous test case, 55 seconds (yarn install 102.96s user 9.30s system 201% cpu 55.686 total).

Logs

   ~/code/yarn-bug-reports   output-buffering  time yarn install
  ➤ YN0000: ┌ Resolution step
  ➤ YN0002: │ @endemolshinegroup/cosmiconfig-typescript-loader@npm:3.0.2 [9a4a3] doesn't provide typescript (pe9669), requested by ts-node
  ➤ YN0002: │ @endemolshinegroup/cosmiconfig-typescript-loader@npm:3.0.2 [c6211] doesn't provide typescript (pc78ba), requested by ts-node
  ➤ YN0002: │ infrastructure@workspace:infrastructure doesn't provide @aws-cdk/aws-logs (p0d64c), requested by datadog-cdk-constructs
  ➤ YN0002: │ infrastructure@workspace:infrastructure doesn't provide @aws-cdk/aws-logs-destinations (p52934), requested by datadog-cdk-constructs
  ➤ YN0002: │ infrastructure@workspace:infrastructure doesn't provide constructs (pdcaf4), requested by datadog-cdk-constructs
  ➤ YN0002: │ infrastructure@workspace:infrastructure doesn't provide jest (pf1db5), requested by @aws-cdk/assert
  ➤ YN0002: │ infrastructure@workspace:infrastructure doesn't provide prettier (pb5d06), requested by eslint-plugin-prettier
  ➤ YN0002: │ yarn-repro@workspace:. doesn't provide graphql-tag (p503cc), requested by @graphql-codegen/typescript-react-apollo
  ➤ YN0000: │ Some peer dependencies are incorrectly met; run yarn explain peer-requirements <hash> for details, where <hash> is the six-letter p-prefixed code
  ➤ YN0000: └ Completed
  ➤ YN0000: ┌ Fetch step
  ➤ YN0013: │ yargs@npm:16.2.0 can't be found in the cache and will be fetched from the remote registry
  ➤ YN0013: │ yargs@npm:17.3.1 can't be found in the cache and will be fetched from the remote registry
  ➤ YN0013: │ yn@npm:3.1.1 can't be found in the cache and will be fetched from the remote registry
  ➤ YN0013: │ yocto-queue@npm:0.1.0 can't be found in the cache and will be fetched from the remote registr
  ➤ YN0013: │ zip-stream@npm:4.1.0 can't be found in the cache and will be fetched from the remote registry
  ➤ YN0000: └ Completed in 49s 836ms
  ➤ YN0000: ┌ Link step
  ➤ YN0007: │ esbuild@npm:0.14.23 must be built because it never has been before or the last one failed
  ➤ YN0007: │ esbuild@npm:0.12.29 must be built because it never has been before or the last one failed
  ➤ YN0000: └ Completed in 5s 10ms
  ➤ YN0000: Done with warnings in 55s 189ms
  yarn install  102.96s user 9.30s system 201% cpu 55.686 total

IMPORTANT: reset state between tests by running:
git clean -fdx && yarn cache clean --all

With the CI variable set

I can recreate a similar install time to the "With Terminal Unfocused
" test by setting the CI environment variable, which also appears to disable the scrolling output.

This takes 53 seconds yarn install 101.41s user 8.71s system 206% cpu 53.305 total.

Logs

   ~/code/yarn-bug-reports   output-buffering  export CI=true
   ~/code/yarn-bug-reports   output-buffering  time yarn install
  ➤ YN0000: ┌ Resolution step
  ➤ YN0002: │ @endemolshinegroup/cosmiconfig-typescript-loader@npm:3.0.2 [9a4a3] doesn't provide typescript (pe9669), requested by ts-node
  ➤ YN0002: │ @endemolshinegroup/cosmiconfig-typescript-loader@npm:3.0.2 [c6211] doesn't provide typescript (pc78ba), requested by ts-node
  ➤ YN0002: │ infrastructure@workspace:infrastructure doesn't provide @aws-cdk/aws-logs (p0d64c), requested by datadog-cdk-constructs
  ➤ YN0002: │ infrastructure@workspace:infrastructure doesn't provide @aws-cdk/aws-logs-destinations (p52934), requested by datadog-cdk-constructs
  ➤ YN0002: │ infrastructure@workspace:infrastructure doesn't provide constructs (pdcaf4), requested by datadog-cdk-constructs
  ➤ YN0002: │ infrastructure@workspace:infrastructure doesn't provide jest (pf1db5), requested by @aws-cdk/assert
  ➤ YN0002: │ infrastructure@workspace:infrastructure doesn't provide prettier (pb5d06), requested by eslint-plugin-prettier
  ➤ YN0002: │ yarn-repro@workspace:. doesn't provide graphql-tag (p503cc), requested by @graphql-codegen/typescript-react-apollo
  ➤ YN0000: │ Some peer dependencies are incorrectly met; run yarn explain peer-requirements <hash> for details, where <hash> is the six-letter p-prefixed code
  ➤ YN0000: └ Completed
  ➤ YN0000: ┌ Fetch step
  ➤ YN0013: │ 22 packages were already cached, 1163 had to be fetched
  ➤ YN0000: └ Completed in 47s 888ms
  ➤ YN0000: ┌ Link step
  ➤ YN0007: │ esbuild@npm:0.14.23 must be built because it never has been before or the last one failed
  ➤ YN0007: │ esbuild@npm:0.12.29 must be built because it never has been before or the last one failed
  ➤ YN0000: └ Completed in 4s 578ms
  ➤ YN0000: Done with warnings in 52s 808ms
  yarn install  101.41s user 8.71s system 206% cpu 53.305 total

Environment

System:
    OS: macOS 12.2.1
    CPU: (10) arm64 Apple M1 Pro
  Binaries:
    Node: 16.14.0 - /private/var/folders/tx/kg437xgx1yv5yx3m0mtm0d8h0000gn/T/xfs-ef13bc38/node
    Yarn: 3.2.0 - /private/var/folders/tx/kg437xgx1yv5yx3m0mtm0d8h0000gn/T/xfs-ef13bc38/yarn
    npm: 8.3.1 - ~/.asdf/plugins/nodejs/shims/npm
  npmPackages:
    jest: 27 => 27.5.1

Additional context

No response

[charpeni]

I thought I was crazy when two coworkers (Intel and M1) didn't have any issues like this, I was the only one and Yarn was so inconsistent: 3, 4, 6, or 8 minutes to install while it was taking ~30 seconds on their machine. Then, I found your post and your Youtube video confirmed we have exactly the same issue. Phew!

We realized that this is only happening if you use iTerm, it is way faster using Terminal.

@opoku found out that we can ignore can't be found in the cache and will be fetched from the remote registry logs and then "fixed" the issue with iTerm with the following configuration in your .yarnrc.yml:

logFilters:
  - code: YN0013
    level: discard

[yarnbot]

Hi! 👋

This issue looks stale, and doesn't feature the reproducible label - which implies that you didn't provide a working reproduction using Sherlock. As a result, it'll be closed in a few days unless a maintainer explicitly vouches for it or you edit your first post to include a formal reproduction (you can use the playground for that).

Note that we require Sherlock reproductions for long-lived issues (rather than standalone git repositories or similar) because we're a small team. Sherlock gives us the ability to check which bugs are still affecting the master branch at any given point, and decreases the amount of code we need to run on our own machines (thus leading to faster bug resolutions). It helps us help you! 😃

If you absolutely cannot reproduce a bug on Sherlock (for example because it's a Windows-only issue), a maintainer will have to manually add the upholded label. Thanks for helping us triaging our repository! 🌟

[blimmer]

Because this bug requires use of iTerm 2 (a popular choice on macOS), I can't create a Sherlock repro. Would a maintainer be able to review and label this appropriately?

[v0lume]

same issue when using webstorm default terminal, m1pro