[Bug]: bad startup performance

[Christoph-AK]

Please confirm that you have:

• Searched existing issues to see if your issue is a duplicate. (If you’ve found a duplicate issue, feel free to add additional information in a comment on it.)
• Reproduced the issue in the latest CLI version.

In which of these areas are you experiencing a problem?

Theme

Expected behavior

Running shopify theme dev --store shop.myshopify.com starts executing immediately.

Actual behavior

Running any command (version as well) takes 5+ seconds to run. For a modern application we are running hundreds of times a day thats not really great.

Verbose output

❯ get-date; shopify theme dev --store shop.myshopify.com --verbose 

Freitag, 2. Juni 2023 15:23:37
2023-06-02T13:23:47.635Z: Running command theme dev

Reproduction steps

1. run any command

Operating System

Windows 11 22H2 (22621.1702)

Shopify CLI version (check your project's package.json if you're not sure)

3.46.2

Shell

powershell with starship

Node version (run node -v if you're not sure)

v16.14.2

What language and version are you using in your application?

ruby 3.1.2p20 (2022-04-12 revision 4491bb740a) [x64-mingw-ucrt], pnpm 8.6.0

[muchisx]

experienced this too ever since I migrated from cli 2.x to 3.x, there's something throttling theme commands vs how it was before

[amcaplan]

I'd recommend running with the --verbose flag and reporting what seems to be taking a lot of time for you. There have been some changes to how authentication works, so it's possible that's behind it, or it could be any of the other things that happen during startup. Hard to improve without some concrete data. Looking forward to seeing what you come up with!

[Christoph-AK]

@amcaplan Thanks for looking into this! I provided the first lines of the verbose output. There is just plain nothing happening for the first 10 seconds, even before the first line of verbose output. My first guess would go in the direction of node startup time - any way to improve that?

[Christoph-AK]

Just leaving this here: https://blog.logrocket.com/snapshot-flags-node-js-v18-8/

If node really is the problem here, there might be some ways to improve startup time.

Any ideas on how to check what actually is the problem here?
I think I might do a run with process monitor hooked up to take a look at syscalls tomorrow.

[amcaplan]

You can also try again setting DEBUG=* in the environment. This will log as it loads the commands, and help understand whether the issue is node itself or some CLI code.

You can also try running node -e "console.log('hello')" to see how node performs on a trivial script.

[Christoph-AK]

Thanks for the pointers!
Running with the Debug env has the same behaviour: 10 seconds nothing, then the first debug entry appears. In that time the Microsoft Defender task is running, so I suspect this to be some antivirus scanning going on. Will try to disable it and run again.

Running `node -e "console.log('hello')"`` returns hello instantly.

[Christoph-AK]

I ran shopify version with process monitor running to take a deeper look.
After running the shell shim, node instantly starts up and begins to load a massive amount of dependencies:

...

until it finally loads the shopify files, runs, and returns instantly.

Adding most of the files node accesses to the allowlist of defender improved performance by ~30%, but it was not the improvement I hoped for.

I would love to try out snapshotting for node, like in https://blog.logrocket.com/snapshot-flags-node-js-v18-8/

Maybe we could create the snapshot on first run and store it.

[amcaplan]

@Christoph-AK thanks for the context! My read of this is that most of the time is taken by loading dependency packages, which is quite slow on Windows compared with Linux or Mac systems, due to a mixture of NTFS and subsystem design issues. Simply put, Windows is not built to run Node, where the common practice is to load many small files on startup.

Unfortunately, this isn't going to be as simple as a snapshot, because:

1. Snapshots are only experimentally supported from 18.8 and on. We are still committed to supporting 16+ for a while. And even then, we shouldn't rely heavily on experimental features.
2. If I understand correctly, snapshots are only supported for 1 file; you can't use it to cache your entire loaded dependency tree.

It's possible we could use pkg to come up with some kind of solution... but at any rate, it's going to be a heavy lift.

If the speed is too slow to deal with, it might be best to try other terminals or set up WSL on your machine, which should be much faster at loading dependencies. Wish I had a better suggestion, but I don't at the moment. Will share your findings with the team, though.

[amcaplan]

@muchisx

experienced this too ever since I migrated from cli 2.x to 3.x, there's something throttling theme commands vs how it was before

Can you elaborate on what you've experienced? What level of slowdown?

[muchisx]

Hey @amcaplan !

It's a similar thing to what @Christoph-AK is experiencing, I also use Windows, 11 in my case.

In CLI 2.x which was running on ruby gems, right? commands and data fetching was fast, so running shopify theme list would return the themes list in a matter of 1s max 2s.

in CLI 3.x now that is running on node, commands like shopify theme list take sometimes up to 10s to display the list.

I guess it's not unusable! but if we can find a solution would be nice.

Below is some samples i took, let me know if you would like me to do other types of tests!

Video Demo with shopify theme pull

Recording.2023-06-08.092343.mp4

shopify theme pull Verbose

pwsh> shopify theme pull --store bboxus --verbose
2023-06-08T14:23:09.273Z: Running command theme pull
  shopify:theme:pull init version: @oclif/core@2.1.4 argv: [ '--store', 'bboxus', '--verbose' ] +0ms
2023-06-08T14:23:09.294Z: Ensuring that the user is authenticated with the Theme API with the following scopes:
[]

2023-06-08T14:23:09.295Z: Ensuring that the user is authenticated with the Admin API with the following scopes for the store bboxus.myshopify.com:
[]

2023-06-08T14:23:09.295Z: Getting session store...
2023-06-08T14:23:09.298Z: Validating existing session against the scopes:
[
  "openid",
  "https://api.shopify.com/auth/shop.admin.graphql",
  "https://api.shopify.com/auth/shop.admin.themes",
  "https://api.shopify.com/auth/partners.collaborator-relationships.readonly",
  "https://api.shopify.com/auth/shop.storefront-renderer.devtools",
  "https://api.shopify.com/auth/partners.app.cli.access"
]
For applications:
{
  "adminApi": {
    "scopes": [],
    "storeFqdn": "bboxus.myshopify.com"
  }
}

2023-06-08T14:23:09.299Z: Sending Identity Introspection request to URL: https://accounts.shopify.com/oauth/introspection
2023-06-08T14:23:09.300Z: Sending POST request to URL https://accounts.shopify.com/oauth/introspection
With request headers:
 - User-Agent: Shopify CLI; v=3.45.1
 - Keep-Alive: timeout=30
 - Sec-CH-UA-PLATFORM: win32
 - Content-Type: application/json

2023-06-08T14:23:09.650Z: Request to https://accounts.shopify.com/oauth/introspection completed in 343 ms
With response headers:
 - cache-control: no-cache, no-store, private, must-revalidate, max-age=0
 - content-type: application/json; charset=utf-8
 - etag: W/"45b43db5a401d675c1e858d04c1a1807"
 - x-request-id: 9ebd2aa2-8be5-4211-ad77-1aa3680adf6a

2023-06-08T14:23:09.653Z: The identity token is valid: true
2023-06-08T14:23:09.653Z:
The validation of the token for application/identity completed with the following results:
- It's expired: true
- It's invalid in identity: false

2023-06-08T14:23:09.653Z: The current session is valid but needs refresh. Refreshing...
2023-06-08T14:23:09.654Z: Sending POST request to URL https://accounts.shopify.com/oauth/token?grant_type=refresh_token&access_token=atkn_3dac631c740ad6fa629e049b994acff02fc6514d9d07fb1c1b7ddebf1e39bc25&refresh_token=atkn_11c08fca1ca33ddd62fab53d156bfe244c7abc8514498ee4c3331b6b7e495d08&client_id=fbdb2649-e327-4907-8f67-908d24cfd7e3
With request headers:
 - User-Agent: Shopify CLI; v=3.45.1
 - Keep-Alive: timeout=30
 - Sec-CH-UA-PLATFORM: win32
 - Content-Type: application/json

2023-06-08T14:23:10.149Z: Request to https://accounts.shopify.com/oauth/token?grant_type=refresh_token&access_token=atkn_3dac631c740ad6fa629e049b994acff02fc6514d9d07fb1c1b7ddebf1e39bc25&refresh_token=atkn_11c08fca1ca33ddd62fab53d156bfe244c7abc8514498ee4c3331b6b7e495d08&client_id=fbdb2649-e327-4907-8f67-908d24cfd7e3 completed in 494 ms
With response headers:
 - cache-control: no-cache, no-store, private, must-revalidate, max-age=0
 - content-type: application/json; charset=utf-8
 - etag: W/"152d79bad47dac1b959115aeabe9db0e"
 - x-request-id: 7fd149d5-6644-4b45-b55e-a170db673329

2023-06-08T14:23:10.151Z: Sending POST request to URL https://accounts.shopify.com/oauth/token?grant_type=urn%3Aietf%3Aparams%3Aoauth%3Agrant-type%3Atoken-exchange&requested_token_type=urn%3Aietf%3Aparams%3Aoauth%3Atoken-type%3Aaccess_token&subject_token_type=urn%3Aietf%3Aparams%3Aoauth%3Atoken-type%3Aaccess_token&client_id=fbdb2649-e327-4907-8f67-908d24cfd7e3&audience=271e16d403dfa18082ffb3d197bd2b5f4479c3fc32736d69296829cbb28d41a6&scope=openid+https%3A%2F%2Fapi.shopify.com%2Fauth%2Fpartners.app.cli.access&subject_token=atkn_c263b1dcd2e54c96310af3225881123367db12db0f0384bf0331192751d35805
With request headers:
 - User-Agent: Shopify CLI; v=3.45.1
 - Keep-Alive: timeout=30
 - Sec-CH-UA-PLATFORM: win32
 - Content-Type: application/json

2023-06-08T14:23:10.151Z: Sending POST request to URL https://accounts.shopify.com/oauth/token?grant_type=urn%3Aietf%3Aparams%3Aoauth%3Agrant-type%3Atoken-exchange&requested_token_type=urn%3Aietf%3Aparams%3Aoauth%3Atoken-type%3Aaccess_token&subject_token_type=urn%3Aietf%3Aparams%3Aoauth%3Atoken-type%3Aaccess_token&client_id=fbdb2649-e327-4907-8f67-908d24cfd7e3&audience=ee139b3d-5861-4d45-b387-1bc3ada7811c&scope=openid+https%3A%2F%2Fapi.shopify.com%2Fauth%2Fshop.storefront-renderer.devtools&subject_token=atkn_c263b1dcd2e54c96310af3225881123367db12db0f0384bf0331192751d35805
With request headers:
 - User-Agent: Shopify CLI; v=3.45.1
 - Keep-Alive: timeout=30
 - Sec-CH-UA-PLATFORM: win32
 - Content-Type: application/json

2023-06-08T14:23:10.513Z: Request to https://accounts.shopify.com/oauth/token?grant_type=urn%3Aietf%3Aparams%3Aoauth%3Agrant-type%3Atoken-exchange&requested_token_type=urn%3Aietf%3Aparams%3Aoauth%3Atoken-type%3Aaccess_token&subject_token_type=urn%3Aietf%3Aparams%3Aoauth%3Atoken-type%3Aaccess_token&client_id=fbdb2649-e327-4907-8f67-908d24cfd7e3&audience=271e16d403dfa18082ffb3d197bd2b5f4479c3fc32736d69296829cbb28d41a6&scope=openid+https%3A%2F%2Fapi.shopify.com%2Fauth%2Fpartners.app.cli.access&subject_token=atkn_c263b1dcd2e54c96310af3225881123367db12db0f0384bf0331192751d35805 completed in 361 ms
With response headers:
 - cache-control: no-cache, no-store, private, must-revalidate, max-age=0
 - content-type: application/json; charset=utf-8
 - etag: W/"e65e0eaaff0d159bf29825ac79ab55c5"
 - x-request-id: b8b108d6-52a4-4a4f-be87-0a3c35cc6c22

2023-06-08T14:23:10.733Z: Request to https://accounts.shopify.com/oauth/token?grant_type=urn%3Aietf%3Aparams%3Aoauth%3Agrant-type%3Atoken-exchange&requested_token_type=urn%3Aietf%3Aparams%3Aoauth%3Atoken-type%3Aaccess_token&subject_token_type=urn%3Aietf%3Aparams%3Aoauth%3Atoken-type%3Aaccess_token&client_id=fbdb2649-e327-4907-8f67-908d24cfd7e3&audience=ee139b3d-5861-4d45-b387-1bc3ada7811c&scope=openid+https%3A%2F%2Fapi.shopify.com%2Fauth%2Fshop.storefront-renderer.devtools&subject_token=atkn_c263b1dcd2e54c96310af3225881123367db12db0f0384bf0331192751d35805 completed in 580 ms
With response headers:
 - cache-control: no-cache, no-store, private, must-revalidate, max-age=0
 - content-type: application/json; charset=utf-8
 - etag: W/"2c6d63060dfaed184b5f89141b44d8ee"
 - x-request-id: 46309b84-199e-41e9-8b1c-e339103fbcb6

2023-06-08T14:23:10.734Z: Sending POST request to URL https://accounts.shopify.com/oauth/token?grant_type=urn%3Aietf%3Aparams%3Aoauth%3Agrant-type%3Atoken-exchange&requested_token_type=urn%3Aietf%3Aparams%3Aoauth%3Atoken-type%3Aaccess_token&subject_token_type=urn%3Aietf%3Aparams%3Aoauth%3Atoken-type%3Aaccess_token&client_id=fbdb2649-e327-4907-8f67-908d24cfd7e3&audience=7ee65a63608843c577db8b23c4d7316ea0a01bd2f7594f8a9c06ea668c1b775c&scope=openid+https%3A%2F%2Fapi.shopify.com%2Fauth%2Fshop.admin.graphql+https%3A%2F%2Fapi.shopify.com%2Fauth%2Fshop.admin.themes+https%3A%2F%2Fapi.shopify.com%2Fauth%2Fpartners.collaborator-relationships.readonly&subject_token=atkn_c263b1dcd2e54c96310af3225881123367db12db0f0384bf0331192751d35805&destination=https%3A%2F%2Fbboxus.myshopify.com%2Fadmin
With request headers:
 - User-Agent: Shopify CLI; v=3.45.1
 - Keep-Alive: timeout=30
 - Sec-CH-UA-PLATFORM: win32
 - Content-Type: application/json

2023-06-08T14:23:11.086Z: Request to https://accounts.shopify.com/oauth/token?grant_type=urn%3Aietf%3Aparams%3Aoauth%3Agrant-type%3Atoken-exchange&requested_token_type=urn%3Aietf%3Aparams%3Aoauth%3Atoken-type%3Aaccess_token&subject_token_type=urn%3Aietf%3Aparams%3Aoauth%3Atoken-type%3Aaccess_token&client_id=fbdb2649-e327-4907-8f67-908d24cfd7e3&audience=7ee65a63608843c577db8b23c4d7316ea0a01bd2f7594f8a9c06ea668c1b775c&scope=openid+https%3A%2F%2Fapi.shopify.com%2Fauth%2Fshop.admin.graphql+https%3A%2F%2Fapi.shopify.com%2Fauth%2Fshop.admin.themes+https%3A%2F%2Fapi.shopify.com%2Fauth%2Fpartners.collaborator-relationships.readonly&subject_token=atkn_c263b1dcd2e54c96310af3225881123367db12db0f0384bf0331192751d35805&destination=https%3A%2F%2Fbboxus.myshopify.com%2Fadmin completed in 351 ms
With response headers:
 - cache-control: no-cache, no-store, private, must-revalidate, max-age=0
 - content-type: application/json; charset=utf-8
 - etag: W/"a66db28c5b83c032f4f82071ec82b255"
 - x-request-id: d1a04257-2255-46ab-bba0-5f7d475113b8

2023-06-08T14:23:11.088Z: Setting session store...
2023-06-08T14:23:11.098Z: Getting development theme...
2023-06-08T14:23:11.669Z: Request to https://bboxus.myshopify.com/admin/api/unstable/themes/124428648546.json?fields=id completed in 569 ms
With response headers:
 - content-type: application/json; charset=utf-8
 - x-request-id: d13bc533-7bbf-40c4-882e-d32ca07e38fb

2023-06-08T14:23:11.695Z:
Running system process:
  · Command: ruby -v
  · Working directory: C:\Users\Migue

2023-06-08T14:23:11.729Z:
Running system process:
  · Command: bundle -v
  · Working directory: C:\Users\Migue

2023-06-08T14:23:12.023Z: Reading the content of file at AppData/Roaming/npm/node_modules/@shopify/theme/node_modules/@shopify/cli-kit/assets/cli-ruby/Gemfile...
2023-06-08T14:23:12.044Z:
Running system process:
  · Command: bundle config set --local path C:\Users\Migue\AppData\Local\shopify-gems-nodejs\Cache
  · Working directory: C:/Users/Migue/AppData/Roaming/npm/node_modules/@shopify/theme/node_modules/@shopify/cli-kit/assets/cli-ruby

2023-06-08T14:23:12.377Z:
Running system process:
  · Command: bundle config set --local without development:test
  · Working directory: C:/Users/Migue/AppData/Roaming/npm/node_modules/@shopify/theme/node_modules/@shopify/cli-kit/assets/cli-ruby

2023-06-08T14:23:12.719Z:
Running system process:
  · Command: bundle install
  · Working directory: C:/Users/Migue/AppData/Roaming/npm/node_modules/@shopify/theme/node_modules/@shopify/cli-kit/assets/cli-ruby

2023-06-08T14:23:13.286Z:
Running system process:
  · Command: bundle exec ruby C:/Users/Migue/AppData/Roaming/npm/node_modules/@shopify/theme/node_modules/@shopify/cli-kit/assets/cli-ruby/bin/shopify theme pull C:\Users\Migue --development-theme-id 124428648546
  · Working directory: C:\Users\Migue

DEBUG GET https://bboxus.myshopify.com/admin/api/unstable/themes.json with request_id: 67d0f303-7b0c-427c-9a89-b1fabd47fbdb
? Select a theme to pull from bboxus.myshopify.com (Navigate up with 'k' and down with 'j', press Enter to select, filter with 'f', enter option with 'e')
> 1.  v3.0.8 | 2 Feb | Klaviyo Popup [live]
  2.  CDSD-23692 [unpublished]
etc...

[amcaplan]

From here it looks like Microsoft is pretty open about being very slow for Node applications. So unless we'd choose to rewrite the CLI in another language (unlikely at the moment), this isn't something we can fix easily.

However, as mentioned above, WSL is a very good option. Additionally, Windows Insider builds have a Dev Drive feature where you can move your npm cache for significantly better performance.

@muchisx it looks like some of what you're experiencing is slowness on refreshing your login. Recall that on CLI2 you'd run a command, get told to log in again, then log in, then run the command and succeed? On CLI3 we take care of this within the command, including refreshing your authentication. We could probably give better UI feedback about what's happening (e.g. a taskbar saying we're refreshing your authentication) but it's impossible to circumvent the need to be certain we have valid authentication before proceeding. That's also why the second run of the command is significantly faster.

[github-actions]

This issue seems inactive. If it's still relevant, please add a comment saying so. Otherwise, take no action.
→ If there's no activity within a week, then a bot will automatically close this.
Thanks for helping to improve Shopify's dev tooling and experience.

P.S. You can learn more about why we stale issues here.

[Christoph-AK]

Not sure if I'm super happy with this being closed. I'm really looking forward to the mitigations in dev drives and will report back with observaitons once I get my hands on that feature, but this is still a really big problem for us, and we cant spare the 6GB and management overhead to run wsl on our dev machines at the time. I would love to see some kind of improvement in windows startup time, but I am unsure if and how this could be achieved in the current system.

Kinde makes this an ideal candidate to rewrite in rust 🦀, doesn't it? 😁

[github-actions]

This issue seems inactive. If it's still relevant, please add a comment saying so. Otherwise, take no action.
→ If there's no activity within a week, then a bot will automatically close this.
Thanks for helping to improve Shopify's dev tooling and experience.

P.S. You can learn more about why we stale issues here.

[julesgilson]

This all sound fairly lame. I think it is obvious that V3 CLI runs very slowly and to say it is a "Windows" thing is not really a valid response. I run node under Windows and Linux as well as in WSL and all other packages do not have extreme differences in performance. Has any analysis been done as to why exactly it runs slow, which dependencies, alternatives etc? Just letting
the issue close appears the lazy option.