pyenv-virtualenv icon indicating copy to clipboard operation
pyenv-virtualenv copied to clipboard
verified publisher icon pyenv

pyenv-virtualenv is very slow on macOS Sequoia

Open kozlek opened this issue 1 year ago • 7 comments

Too many issues will kill our team's development velocity, drastically. Make sure you have checked all steps below.

Prerequisite

  • [x] Make sure your problem is not listed in the common build problems.
  • [x] Make sure no duplicated issue has already been reported in the pyenv-virtualenv issues. You should look in closed issues, too.
  • [x] Make sure you are not asking us to help solving your specific issue.
    • GitHub issues is opened mainly for development purposes. If you want to ask someone to help solving your problem, go to some community site like Gitter, StackOverflow, etc.
  • [x] Make sure your problem is not derived from packaging (e.g. Homebrew).
    • Please refer to the package documentation for the installation issues, etc.
  • [x] Make sure your problem is not derived from other plugins.
    • This repository is maintaining the pyenv-virtualenv plugin only. Please refrain from reporting issues of other plugins here.

Description

  • [x] Platform information (e.g. Ubuntu Linux 20.04): macOS 15.0 Sequoia
  • [x] OS architecture (e.g. amd64): amd64 (MacbookPro 14,3)
  • [x] pyenv version: v2.4.13
  • [x] pyenv-virtualenv version: v1.2.4
  • [x] Python version: 3.12.6
  • [x] virtualenv version (if installed): none

I was using pyenv & pyenv-virtualenv on macOS 12.x Monterey for 2 years with great success. Yesterday, I updated to macOS 15.0 Sequoia (clean install). The shell was very slow with pyenv-virtualenv autoloading enabled. It takes around 1.2 seconds when hitting a blank line in the shell.

I downgraded to macOS 13.x Ventura (clean install again) and the shell was instant again.

I don't expect you to fix macOS, but I wanted to report my experience with Sequoia to see if others users have the same problem. Apart from pyenv-virtualenv, pyenv + jenv + rbenv were also a bit slower. The rest of the apps were working well. I suspect Apple to have changed something with the terminal / shell...

I'll stick to Ventura for sometimes, and I'll give a try to Sonoma to see.

kozlek avatar Sep 20 '24 08:09 kozlek

I did a macOS 14.7 Sonoma clean install on an external SSD and pyenv-virtualenv is behaving normally, without any delays.

At least on my platform, macOS Sequoia has a huge issue with some shell programs.

I recommend to postpone the Sequoia upgrade until this is fixed on macOS side.

kozlek avatar Sep 21 '24 11:09 kozlek

I encountered this same problem yesterday on my Intel Mac running macOS 14.7 (Sonoma) when I updated from Xcode 15.3 to Xcode 16. I presume that your fresh install of macOS 15 (Sequoia) had Xcode 16, and I'd be curious to see whether downgrading only Xcode without downgrading the OS would solve the problem. I'm also curious about whether this is a problem only on Intel Macs or if it's a problem on Apple Silicon as well.

I noticed a variety of pyenv and pyenv-virtualenv commands being much slower, and I was able to figure out that the command pyenv sh-activate --quiet command run in the shell hook was taking most of the time when I hit "Enter" on a blank line. I ran the following command to help test out the problem:

time env -i bash -cx 'export PYENV_DEBUG=1; command pyenv sh-activate --quiet'

With Xcode 16, the command takes over 10 s to execute, while with Xcode 15.3, the command takes ~0.3 s to execute.

I can help with debugging the problem because I can't delay upgrading Xcode indefinitely. However, I have no clue how to profile shell scripts. If anyone has tooling recommendations, I can hopefully figure out exactly where the regression is happening.

aphedges avatar Sep 26 '24 18:09 aphedges

However, I have no clue how to profile shell scripts.

https://github.com/pyenv/pyenv-virtualenv/issues/259#issuecomment-1282754854:

Try localizing the issue by timing the code that runs at prompt with:

export PS4='+($(date "+%s.%N")) (${BASH_SOURCE:-}:${LINENO}): ${FUNCNAME[0]:+${FUNCNAME[0]}(): }'
set -x
<reproduce the problem>
set +x

Also add the same date invocation to PS4 assignments throughout Pyenv and Pyenv-Virtualenv and set PYENV_DEBUG=1

native-api avatar Sep 26 '24 21:09 native-api

I forgot to mention this, but I switched to an Apple silicon laptop a week or two after encountering this issue, and I had no problems using Xcode 16 on it. I think this regression is purely for Intel Mac users.

Someone else is obviously free to debug this, but I'm not going to spend the time debugging it myself.

aphedges avatar Oct 23 '24 19:10 aphedges

Here's the timed output from my machine:

$ PS4='+($(date "+%s.%N")) (${BASH_SOURCE:-}:${LINENO}): ${FUNCNAME[0]:+${FUNCNAME[0]}(): }' time bash -x /usr/local/bin/pyenv sh-activate --quiet
+(1735257413.707286000) (/usr/local/bin/pyenv:2): set -e
+(1735257413.717032000) (/usr/local/bin/pyenv:4): '[' sh-activate = --debug ']'
+(1735257413.729358000) (/usr/local/bin/pyenv:9): '[' -n '' ']'
+(1735257413.741455000) (/usr/local/bin/pyenv:23): enable -f /usr/local/bin/../libexec/pyenv-realpath.dylib realpath
+(1735257413.754514000) (/usr/local/bin/pyenv:30): '[' -z '' ']'
++(1735257413.767650000) (/usr/local/bin/pyenv:32): type -P readlink
+(1735257413.778545000) (/usr/local/bin/pyenv:32): READLINK=/usr/local/opt/coreutils/libexec/gnubin/readlink
+(1735257413.788991000) (/usr/local/bin/pyenv:33): '[' -n /usr/local/opt/coreutils/libexec/gnubin/readlink ']'
+(1735257413.802350000) (/usr/local/bin/pyenv:58): '[' -z /Users/axa/.pyenv ']'
+(1735257413.815300000) (/usr/local/bin/pyenv:61): PYENV_ROOT=/Users/axa/.pyenv
+(1735257413.828289000) (/usr/local/bin/pyenv:63): export PYENV_ROOT
+(1735257413.839098000) (/usr/local/bin/pyenv:65): '[' -z '' ']'
+(1735257413.852871000) (/usr/local/bin/pyenv:66): PYENV_DIR=/Users/axa
+(1735257413.868479000) (/usr/local/bin/pyenv:69): '[' '!' -d /Users/axa ']'
+(1735257413.882083000) (/usr/local/bin/pyenv:69): '[' '!' -e /Users/axa ']'
++(1735257413.897309000) (/usr/local/bin/pyenv:73): cd /Users/axa
++(1735257413.910416000) (/usr/local/bin/pyenv:73): echo /Users/axa
+(1735257413.921637000) (/usr/local/bin/pyenv:73): PYENV_DIR=/Users/axa
+(1735257413.932492000) (/usr/local/bin/pyenv:74): export PYENV_DIR
+(1735257413.943222000) (/usr/local/bin/pyenv:77): shopt -s nullglob
++(1735257413.953742000) (/usr/local/bin/pyenv:79): abs_dirname /usr/local/bin/pyenv
++(1735257413.963952000) (/usr/local/bin/pyenv:40): abs_dirname(): local path=/usr/local/bin/pyenv
++(1735257413.974300000) (/usr/local/bin/pyenv:44): abs_dirname(): '[' -n /usr/local/bin/pyenv ']'
++(1735257413.983151000) (/usr/local/bin/pyenv:45): abs_dirname(): cd_path=/usr/local/bin
++(1735257413.992398000) (/usr/local/bin/pyenv:46): abs_dirname(): [[ /usr/local/bin != \/\u\s\r\/\l\o\c\a\l\/\b\i\n\/\p\y\e\n\v ]]
++(1735257414.001208000) (/usr/local/bin/pyenv:47): abs_dirname(): cd /usr/local/bin
++(1735257414.009919000) (/usr/local/bin/pyenv:49): abs_dirname(): name=pyenv
+++(1735257414.019198000) (/usr/local/bin/pyenv:50): abs_dirname(): resolve_link pyenv
+++(1735257414.027892000) (/usr/local/bin/pyenv:36): resolve_link(): /usr/local/opt/coreutils/libexec/gnubin/readlink pyenv
++(1735257414.044531000) (/usr/local/bin/pyenv:50): abs_dirname(): path=../Cellar/pyenv/2.5.0/bin/pyenv
++(1735257414.053510000) (/usr/local/bin/pyenv:44): abs_dirname(): '[' -n ../Cellar/pyenv/2.5.0/bin/pyenv ']'
++(1735257414.062451000) (/usr/local/bin/pyenv:45): abs_dirname(): cd_path=../Cellar/pyenv/2.5.0/bin
++(1735257414.071110000) (/usr/local/bin/pyenv:46): abs_dirname(): [[ ../Cellar/pyenv/2.5.0/bin != \.\.\/\C\e\l\l\a\r\/\p\y\e\n\v\/\2\.\5\.\0\/\b\i\n\/\p\y\e\n\v ]]
++(1735257414.080631000) (/usr/local/bin/pyenv:47): abs_dirname(): cd ../Cellar/pyenv/2.5.0/bin
++(1735257414.089569000) (/usr/local/bin/pyenv:49): abs_dirname(): name=pyenv
+++(1735257414.101663000) (/usr/local/bin/pyenv:50): abs_dirname(): resolve_link pyenv
+++(1735257414.111082000) (/usr/local/bin/pyenv:36): resolve_link(): /usr/local/opt/coreutils/libexec/gnubin/readlink pyenv
++(1735257414.129154000) (/usr/local/bin/pyenv:50): abs_dirname(): path=../libexec/pyenv
++(1735257414.137597000) (/usr/local/bin/pyenv:44): abs_dirname(): '[' -n ../libexec/pyenv ']'
++(1735257414.146025000) (/usr/local/bin/pyenv:45): abs_dirname(): cd_path=../libexec
++(1735257414.155138000) (/usr/local/bin/pyenv:46): abs_dirname(): [[ ../libexec != \.\.\/\l\i\b\e\x\e\c\/\p\y\e\n\v ]]
++(1735257414.164070000) (/usr/local/bin/pyenv:47): abs_dirname(): cd ../libexec
++(1735257414.172947000) (/usr/local/bin/pyenv:49): abs_dirname(): name=pyenv
+++(1735257414.182324000) (/usr/local/bin/pyenv:50): abs_dirname(): resolve_link pyenv
+++(1735257414.191762000) (/usr/local/bin/pyenv:36): resolve_link(): /usr/local/opt/coreutils/libexec/gnubin/readlink pyenv
+++(1735257414.207854000) (/usr/local/bin/pyenv:50): abs_dirname(): true
++(1735257414.217041000) (/usr/local/bin/pyenv:50): abs_dirname(): path=
++(1735257414.226502000) (/usr/local/bin/pyenv:44): abs_dirname(): '[' -n '' ']'
++(1735257414.235250000) (/usr/local/bin/pyenv:53): abs_dirname(): echo /usr/local/Cellar/pyenv/2.5.0/libexec
+(1735257414.245037000) (/usr/local/bin/pyenv:79): bin_path=/usr/local/Cellar/pyenv/2.5.0/libexec
+(1735257414.255293000) (/usr/local/bin/pyenv:80): for plugin_bin in "${bin_path%/*}"/plugins/*/bin
+(1735257414.263904000) (/usr/local/bin/pyenv:81): PATH=/usr/local/Cellar/pyenv/2.5.0/plugins/python-build/bin:/opt/homebrew/opt/curl/bin:/Users/axa/.asdf/shims:/usr/local/opt/asdf/libexec/bin:/usr/local/Cellar/pyenv-virtualenv/1.2.4/shims:/Users/axa/.pyenv/shims:/Users/axa/.pyenv/bin:/Users/axa/.cargo/bin:/usr/local/opt/coreutils/libexec/gnubin:/usr/local/sbin:/usr/local/bin:/Users/axa/.local/bin:/usr/local/bin:/usr/local/bin:/System/Cryptexes/App/usr/bin:/usr/bin:/bin:/usr/sbin:/sbin:/var/run/com.apple.security.cryptexd/codex.system/bootstrap/usr/local/bin:/var/run/com.apple.security.cryptexd/codex.system/bootstrap/usr/bin:/var/run/com.apple.security.cryptexd/codex.system/bootstrap/usr/appleinternal/bin:/Applications/iTerm.app/Contents/Resources/utilities:/Users/axa/Library/Android/sdk/platform-tools
+(1735257414.272779000) (/usr/local/bin/pyenv:85): '[' /usr/local/Cellar/pyenv/2.5.0 '!=' /Users/axa/.pyenv ']'
+(1735257414.282625000) (/usr/local/bin/pyenv:90): export PATH=/usr/local/Cellar/pyenv/2.5.0/libexec:/usr/local/Cellar/pyenv/2.5.0/plugins/python-build/bin:/opt/homebrew/opt/curl/bin:/Users/axa/.asdf/shims:/usr/local/opt/asdf/libexec/bin:/usr/local/Cellar/pyenv-virtualenv/1.2.4/shims:/Users/axa/.pyenv/shims:/Users/axa/.pyenv/bin:/Users/axa/.cargo/bin:/usr/local/opt/coreutils/libexec/gnubin:/usr/local/sbin:/usr/local/bin:/Users/axa/.local/bin:/usr/local/bin:/usr/local/bin:/System/Cryptexes/App/usr/bin:/usr/bin:/bin:/usr/sbin:/sbin:/var/run/com.apple.security.cryptexd/codex.system/bootstrap/usr/local/bin:/var/run/com.apple.security.cryptexd/codex.system/bootstrap/usr/bin:/var/run/com.apple.security.cryptexd/codex.system/bootstrap/usr/appleinternal/bin:/Applications/iTerm.app/Contents/Resources/utilities:/Users/axa/Library/Android/sdk/platform-tools
+(1735257414.291685000) (/usr/local/bin/pyenv:90): PATH=/usr/local/Cellar/pyenv/2.5.0/libexec:/usr/local/Cellar/pyenv/2.5.0/plugins/python-build/bin:/opt/homebrew/opt/curl/bin:/Users/axa/.asdf/shims:/usr/local/opt/asdf/libexec/bin:/usr/local/Cellar/pyenv-virtualenv/1.2.4/shims:/Users/axa/.pyenv/shims:/Users/axa/.pyenv/bin:/Users/axa/.cargo/bin:/usr/local/opt/coreutils/libexec/gnubin:/usr/local/sbin:/usr/local/bin:/Users/axa/.local/bin:/usr/local/bin:/usr/local/bin:/System/Cryptexes/App/usr/bin:/usr/bin:/bin:/usr/sbin:/sbin:/var/run/com.apple.security.cryptexd/codex.system/bootstrap/usr/local/bin:/var/run/com.apple.security.cryptexd/codex.system/bootstrap/usr/bin:/var/run/com.apple.security.cryptexd/codex.system/bootstrap/usr/appleinternal/bin:/Applications/iTerm.app/Contents/Resources/utilities:/Users/axa/Library/Android/sdk/platform-tools
+(1735257414.300668000) (/usr/local/bin/pyenv:92): PYENV_HOOK_PATH=:/Users/axa/.pyenv/pyenv.d
+(1735257414.309510000) (/usr/local/bin/pyenv:93): '[' /usr/local/Cellar/pyenv/2.5.0 '!=' /Users/axa/.pyenv ']'
+(1735257414.319152000) (/usr/local/bin/pyenv:95): PYENV_HOOK_PATH=:/Users/axa/.pyenv/pyenv.d:/usr/local/Cellar/pyenv/2.5.0/pyenv.d
+(1735257414.328590000) (/usr/local/bin/pyenv:97): PYENV_HOOK_PATH=:/Users/axa/.pyenv/pyenv.d:/usr/local/Cellar/pyenv/2.5.0/pyenv.d:/usr/etc/pyenv.d:/usr/local/etc/pyenv.d:/etc/pyenv.d:/usr/lib/pyenv/hooks
+(1735257414.337478000) (/usr/local/bin/pyenv:101): PYENV_HOOK_PATH=/Users/axa/.pyenv/pyenv.d:/usr/local/Cellar/pyenv/2.5.0/pyenv.d:/usr/etc/pyenv.d:/usr/local/etc/pyenv.d:/etc/pyenv.d:/usr/lib/pyenv/hooks
+(1735257414.347152000) (/usr/local/bin/pyenv:102): export PYENV_HOOK_PATH
+(1735257414.356199000) (/usr/local/bin/pyenv:104): shopt -u nullglob
+(1735257414.365002000) (/usr/local/bin/pyenv:107): command=sh-activate
+(1735257414.374405000) (/usr/local/bin/pyenv:108): case "$command" in
++(1735257414.385512000) (/usr/local/bin/pyenv:121): command -v pyenv-sh-activate
+(1735257414.394983000) (/usr/local/bin/pyenv:121): command_path=/usr/local/bin/pyenv-sh-activate
+(1735257414.403592000) (/usr/local/bin/pyenv:122): '[' -z /usr/local/bin/pyenv-sh-activate ']'
+(1735257414.412640000) (/usr/local/bin/pyenv:130): shift 1
+(1735257414.421487000) (/usr/local/bin/pyenv:131): '[' --quiet = --help ']'
+(1735257414.430203000) (/usr/local/bin/pyenv:138): exec /usr/local/bin/pyenv-sh-activate --quiet
false
        1.05 real         0.12 user         0.20 sys

Then the call to pyenv-sh-activate:

$ PATH="/usr/local/Cellar/pyenv/2.5.0/libexec:$PATH" PS4='+($(date "+%s.%N")) (${BASH_SOURCE:-}:${LINENO}): ${FUNCNAME[0]:+${FUNCNAME[0]}(): }' PYENV_HOOK_PATH=/Users/axa/.pyenv/pyenv.d:/usr/local/Cellar/pyenv/2.5.0/pyenv.d:/usr/etc/pyenv.d:/usr/local/etc/pyenv.d:/etc/pyenv.d:/usr/lib/pyenv/hooks time bash -x /usr/local/bin/pyenv-sh-activate --quiet
+(1735257993.285294000) (/usr/local/bin/pyenv-sh-activate:14): set -e
+(1735257993.295018000) (/usr/local/bin/pyenv-sh-activate:15): '[' -n '' ']'
+(1735257993.305093000) (/usr/local/bin/pyenv-sh-activate:17): '[' -z /Users/axa/.pyenv ']'
+(1735257993.314298000) (/usr/local/bin/pyenv-sh-activate:25): unset FORCE
+(1735257993.323911000) (/usr/local/bin/pyenv-sh-activate:26): unset QUIET
+(1735257993.333091000) (/usr/local/bin/pyenv-sh-activate:31): declare -a before_hooks after_hooks
+(1735257993.342439000) (/usr/local/bin/pyenv-sh-activate:44): OLDIFS='
'
+(1735257993.351376000) (/usr/local/bin/pyenv-sh-activate:45): IFS='
'
+(1735257993.360294000) (/usr/local/bin/pyenv-sh-activate:45): scripts=(`pyenv-hooks activate`)
++(1735257993.369588000) (/usr/local/bin/pyenv-sh-activate:45): pyenv-hooks activate
+(1735257993.398014000) (/usr/local/bin/pyenv-sh-activate:46): IFS='
'
+(1735257993.407585000) (/usr/local/bin/pyenv-sh-activate:49): '[' 1 -gt 0 ']'
+(1735257993.416895000) (/usr/local/bin/pyenv-sh-activate:50): case "$1" in
+(1735257993.425927000) (/usr/local/bin/pyenv-sh-activate:60): QUIET=1
+(1735257993.435898000) (/usr/local/bin/pyenv-sh-activate:73): shift 1
+(1735257993.444574000) (/usr/local/bin/pyenv-sh-activate:49): '[' 0 -gt 0 ']'
+(1735257993.454808000) (/usr/local/bin/pyenv-sh-activate:81): no_shell=
+(1735257993.463386000) (/usr/local/bin/pyenv-sh-activate:82): versions=("$@")
+(1735257993.473687000) (/usr/local/bin/pyenv-sh-activate:83): current_versions=()
+(1735257993.485190000) (/usr/local/bin/pyenv-sh-activate:84): '[' -z '' ']'
+(1735257993.495583000) (/usr/local/bin/pyenv-sh-activate:85): no_shell=1
+(1735257993.506443000) (/usr/local/bin/pyenv-sh-activate:86): get_current_versions
+(1735257993.515385000) (/usr/local/bin/pyenv-sh-activate:77): get_current_versions(): local IFS=:
+(1735257993.524527000) (/usr/local/bin/pyenv-sh-activate:78): get_current_versions(): current_versions=($(pyenv-version-name 2> /dev/null))
++(1735257993.534925000) (/usr/local/bin/pyenv-sh-activate:78): get_current_versions(): pyenv-version-name
+(1735257993.617218000) (/usr/local/bin/pyenv-sh-activate:87): versions=("${current_versions[@]}")
+(1735257993.626618000) (/usr/local/bin/pyenv-sh-activate:90): '[' -z 1 ']'
+(1735257993.635276000) (/usr/local/bin/pyenv-sh-activate:96): venv=system
+(1735257993.644949000) (/usr/local/bin/pyenv-sh-activate:98): '[' -n '' ']'
+(1735257993.654518000) (/usr/local/bin/pyenv-sh-activate:111): pyenv-virtualenv-prefix system
+(1735257993.704050000) (/usr/local/bin/pyenv-sh-activate:113): '[' -n system ']'
+(1735257993.712654000) (/usr/local/bin/pyenv-sh-activate:114): new_venv=system/envs/system
+(1735257993.722326000) (/usr/local/bin/pyenv-sh-activate:115): pyenv-virtualenv-prefix system/envs/system
+(1735257993.916236000) (/usr/local/bin/pyenv-sh-activate:119): '[' -z 1 ']'
+(1735257993.925403000) (/usr/local/bin/pyenv-sh-activate:122): echo false
false
+(1735257993.934596000) (/usr/local/bin/pyenv-sh-activate:123): exit 1
        0.67 real         0.21 user         0.35 sys

It's a 2019 13-inch MacBook Pro, 2.8GHz i7, Sequoia 15.1.1.

If I'm not outputting debug information it's faster, but not particularly fast:

$ time _pyenv_virtualenv_hook

real	0m0.410s
user	0m0.131s
sys	0m0.200s

andrewaylett avatar Dec 27 '24 00:12 andrewaylett

I'm not sure if this is related to the new macOS version or not, but I have long noticed that pyenv-virtualenvs is incredibly slow, especially if you have many virtual environments (I currently have 128). Since that is called during pyenv-sh-activate, I imagine that may be part of the problem.

I've been digging into this and found the call from pyenv-virtualenvs --> pyenv-virtualenv-prefix --> pyenv-prefix to be the source of the slowness.

I'll put up a PR soon with a fix.

samdoran avatar Feb 13 '25 16:02 samdoran

@kozlek Try out the changes in #502 and see if that helps things any.

samdoran avatar Feb 13 '25 18:02 samdoran