Skip to content
This repository has been archived by the owner. It is now read-only.

`npm config get prefix` takes incredibly long (7 - 70 seconds) #14458

Open
polybuildr opened this Issue Oct 28, 2016 · 32 comments

Comments

Projects
None yet
@polybuildr
Copy link

polybuildr commented Oct 28, 2016

I'm opening this issue because:

  • Other

What's going wrong?

npm config get prefix takes incredibly long. I was chasing this issue in creationix/nvm#1261 where nvm was taking incredibly long to load, and then realised that it was just the npm config get prefix command that was responsible for 95%+ of the slowdown.

How can the CLI team reproduce the problem?

Unfortunately, this is a new machine and this problem has been happening from the first time I installed npm using nvm. Fresh installs of nvm haven't changed anything, the slowdown is still there.

supporting information:

  • npm -v prints: 3.10.3
  • node -v prints: v6.7.0
  • npm config get registry prints: https://registry.npmjs.org/
  • Ubuntu 16.04, Skylake i7 processor
  • shell: zsh (but similar problems also occurred when using bash)

I understand that the original issue was when using nvm, but since it was specifically the npm command that took extremely long, I came here to figure out why. If there is any further profiling or debugging to do, I would love to get to the bottom of this.

@legodude17

This comment has been minimized.

Copy link
Contributor

legodude17 commented Oct 28, 2016

Can you send in a time "npm config get prefix"? Also could you get the syscalls that are taking up that time?

@polybuildr

This comment has been minimized.

Copy link
Author

polybuildr commented Oct 28, 2016

Another thing I forgot to mention is that this only happens the first time it is called. Basically the first time after boot, after which it's just a few hundred milliseconds for all successive calls. I'll reboot and get a time. Also, I can strace the command, but I'm not sure how to do a time-based profile of it. Any suggestions? Or should I run a profiler and see what function calls are made?

@legodude17

This comment has been minimized.

Copy link
Contributor

legodude17 commented Oct 28, 2016

I think I meant strace. Sorry for the confusion. ☹️ Also, it is really odd that it only happens on the first time. Do you have any strange config?

@polybuildr

This comment has been minimized.

Copy link
Author

polybuildr commented Oct 28, 2016

Yeah, it seems rather strange. I don't think I have any strange config, in fact I don't think I have any custom config at all:

[vivek@matrix] ~ $ npm config list
; cli configs
user-agent = "npm/3.10.3 node/v6.7.0 linux x64"

; userconfig /home/vivek/.npmrc
v6.7.0 = true

; node bin location = /home/vivek/.nvm/versions/node/v6.7.0/bin/node
; cwd = /home/vivek
; HOME = /home/vivek
; "npm config ls -l" to show all defaults.
@legodude17

This comment has been minimized.

Copy link
Contributor

legodude17 commented Oct 28, 2016

Any idea why this is happening @KenanY or @othiym23 or @zkat?

@ljharb

This comment has been minimized.

Copy link
Contributor

ljharb commented Oct 28, 2016

fwiw, npm config get prefix is also the slowest part of http://nvm.sh, by a long shot - if there's a faster way that's equally reliable to get the prefix setting, i'd love to use that instead.

@legodude17

This comment has been minimized.

Copy link
Contributor

legodude17 commented Oct 28, 2016

@ljharb, if you look at the top, you will see that this issue was opened from @polybuildr investigating that issue in nvm. Another way to do it would be npm prefix -g, but that might not be faster.

@ljharb

This comment has been minimized.

Copy link
Contributor

ljharb commented Oct 28, 2016

@legodude17 yes, if you look at the linked nvm issue, you'll see that i requested they file this very issue. npm prefix -g is an alternative i'll look into, thanks.

@legodude17

This comment has been minimized.

Copy link
Contributor

legodude17 commented Oct 28, 2016

Speaking of npm prefix -g, @polybuildr, can you try time npm config get prefix and time npm prefix -g?

@zkat

This comment has been minimized.

Copy link
Member

zkat commented Oct 28, 2016

🤔 I wonder why it hangs like that.

Our startup process could use some work, and it generally looks like this is an occasional hiccup -- the bulk of the startup process is just reading config files and loading dependencies. Some of those are bigger than others and maybe not necessary, but this is worth taking a look at. 7+ seconds is kinda extreme.

@zkat zkat added the performance label Oct 28, 2016

@polybuildr

This comment has been minimized.

Copy link
Author

polybuildr commented Oct 29, 2016

Here is the output of zsh time:

https://gist.github.com/polybuildr/4e9d15508219d55b785de0b0eabe69c8

I'm not sure there is much to be gained by the comparison between npm config get prefix and npm -g prefix because even in just npm config get prefix I see variations between 5 seconds and 70 seconds.

I'll run an strace on next boot.

@legodude17

This comment has been minimized.

Copy link
Contributor

legodude17 commented Oct 29, 2016

Ok. So npm prefix -g doesn't help much. The strace output will hopefully help.

@polybuildr

This comment has been minimized.

Copy link
Author

polybuildr commented Oct 30, 2016

I ran strace -r (print relative time deltas after each command). The output is really large, but here it is:

http://paste.ubuntu.com/23400796/

I'll run another strace with the absolute time printed and I'll also try ltrace later maybe, if that will help.

@polybuildr

This comment has been minimized.

Copy link
Author

polybuildr commented Oct 30, 2016

And here is the output of strace -ttt: http://paste.ubuntu.com/23403626/

@watilde

This comment has been minimized.

Copy link
Contributor

watilde commented Nov 1, 2016

@martinheidegger

This comment has been minimized.

Copy link

martinheidegger commented Dec 6, 2016

I have been looking into the nvm issue as well in order to figure out why the nvm is so slow to start. In my research I figured that npm is the slowest part of nvm.

On my machine nvm takes almost 3 seconds to start up. I wrote some old-school tests for the performance and they showed that most operations are quick but for a few tasks it has to use npm which makes it slow.

https://github.com/martinheidegger/nvm/tree/debug/performance

(It writes the results in the timings.txt in the $NVM_DIR)

Particularly interesting is npm config get prefix which - once called - consumes 0.5 seconds itself in the test environment. To make sure that its not a recent issue I wrote some performance tests that came up with the avg 0.5 seconds:
https://gist.github.com/martinheidegger/32d00e90e0163a22a4ffc78df796001e

@martinheidegger

This comment has been minimized.

Copy link

martinheidegger commented Dec 6, 2016

I updated the tests by running a hack version of npm config that excludes all the npm command line overhead and just loads the data. It seems like more than half of the time is spent on things other than "loading the config". Would be be reasonable to extract the lib/config code into a separate package that it turn could be improved for performance?

@legodude17

This comment has been minimized.

Copy link
Contributor

legodude17 commented Dec 7, 2016

@ljharb

This comment has been minimized.

Copy link
Contributor

ljharb commented Dec 7, 2016

@legodude17 if that package was created, would a PR be accepted that switched to use it? (to ensure that npm won't break that functionality in the future)

@legodude17

This comment has been minimized.

Copy link
Contributor

legodude17 commented Dec 7, 2016

I would say "no", but I am not on the CLI team, so maybe ask @othiym23?

@zkat

This comment has been minimized.

Copy link
Member

zkat commented Dec 7, 2016

It is not a high priority right now, but we've definitely been looking at what exactly is causing the slowdown, and it's a mixture of several things. Config itself isn't even half of it. The most noticeable thing is spending ~200ms on a single one of our dependencies (which, in the case of npm prefix -g is not necessary).

But the way that stuff is factored right now makes it fairly tricky to lazy-load: not impossible, but one of us needs to spend Actual Time on it. The rest involves a long-term project to get rid of the massive global config-object in favor of something a bit more granular, but we really haven't gotten to the point of being able to design that yet.

@ljharb I'd say to go and make that PR if it weren't a thing that required more serious architectural planning/design from the core team. I'm sure if a community member benchmarks the actual startup process and finds a minimal-impact way to cleanly and reliably lazy-load said dependencies and is willing to do a little bit of back-and-forth, we might look at a PR. But please don't do the whole thing with all the tests before talking about it with us, cause I can't guarantee we'd pull it in. That would be a nearly 50% speedup right there on startup.

I am concerned, though, about why it spikes to 7-70 seconds, as I can't reproduce the particular thing that @polybuildr is mentioning. If we had benchmark information about where all that time is going, we might even be able to target a more specific bit, but my best guess right now is that it's just a disk access hiccup from having to do all the work of loading said Big Dep.

@martinheidegger

This comment has been minimized.

Copy link

martinheidegger commented Dec 13, 2016

I read the code in lib/config/find-prefix.js and found quite a few steps that could increase performance and those are actually logical overlaps with the Node.js code. I asked Node.js/help if & why the code is split and it seems that it would be possible to ask/propose an API to node.js to receive the prefix quicker.

If npm wanted to use that, they should file an issue or pull request to make it public API.

Would an API like: module.prefix be useful to NPM?

@npm-robot

This comment has been minimized.

Copy link

npm-robot commented Jun 19, 2017

We're closing this issue as it has gone thirty days without activity. In our experience if an issue has gone thirty days without any activity then it's unlikely to be addressed. In the case of bug reports, often the underlying issue will be addressed but finding related issues is quite difficult and often incomplete.

If this was a bug report and it is still relevant then we encourage you to open it again as a new issue. If this was a feature request then you should feel free to open it again, or even better open a PR.

For more information about our new issue aging policies and why we've instituted them please see our blog post.

@npm-robot npm-robot closed this Jun 19, 2017

@ljharb

This comment has been minimized.

Copy link
Contributor

ljharb commented Jun 19, 2017

This is causing huge slowdowns in nvm, so it'd be appreciated if this could be left open until it's addressed.

@KenanY KenanY removed the bot-closed label Jun 19, 2017

@KenanY KenanY reopened this Jun 19, 2017

@ljharb

This comment has been minimized.

Copy link
Contributor

ljharb commented Jun 19, 2017

@KenanY thank you!

@ljharb

This comment has been minimized.

Copy link
Contributor

ljharb commented Jul 10, 2017

(ping, to avoid npmbot carnage)

@ljharb

This comment has been minimized.

Copy link
Contributor

ljharb commented Aug 3, 2017

(ping again)

@PeterDaveHello

This comment has been minimized.

Copy link
Contributor

PeterDaveHello commented Oct 15, 2017

(help ping)

@williscool

This comment has been minimized.

Copy link

williscool commented Oct 28, 2017

(Ping like the other cool kids.)

Also you can very consistently reproduce this on Windows Subsystem for Linux (WSL) aka Bash on Windows.

It happens literally every time on every shell invocation without fail.

@Worlor

This comment has been minimized.

Copy link

Worlor commented Nov 10, 2017

Hello,

I got this issue with npm 5.5.1 on Windows 7
NodeJs v8.9.1
npm problem

@cristianl

This comment has been minimized.

Copy link

cristianl commented Nov 18, 2017

Not that another ping is needed, but just a heads-up — besides slow shell startup, this may be causing PATH bugs in other applications: SublimeTextIssues/Core#1877

@nylen

This comment has been minimized.

Copy link

nylen commented Feb 20, 2018

It looks like the long load times here are mostly explainable by filesystem reads. Here is what I see after a fresh boot / manual cache clear on a small ARM thing similar to a Raspberry Pi:

$ time npm --version
5.6.0

real	0m10.582s
user	0m2.510s
sys	0m3.490s

Then subsequent runs of npm --version are much faster:

$ time npm --version
5.6.0

real    0m2.844s
user    0m2.545s
sys     0m0.170s

npm config get prefix is slightly slower but pretty comparable.

So npm is simply loading a lot of stuff for this low-powered system to deal with (storage reads are slow). This looks better when system caches are primed, but it doesn't have a very powerful CPU either so we still spend about 3 seconds.

For anyone looking to address this issue within npm, it will be useful to debug the loading sequence on a Raspberry Pi. These links should be helpful:

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
You can’t perform that action at this time.