Closed karrtikr closed 5 months ago
@deepak1556 do you know why spawn would be blocking the thread for so long here?
Profiles at https://github.com/microsoft/vscode-python/issues/21755#issuecomment-1730302574
Note this is when spawning the conda binary, similarly spawning REG binaries can seldomly be like this. But python binaries are much cheaper for some reason.
It's not just us, the git extension while spawning also runs into this:
do you know why spawn would be blocking the thread for so long here?
This was my observation a few years ago as well ( https://github.com/microsoft/vscode-python/issues/15813#issue-844892343) Back then I reached out to jrieken , and he indicated that in node, spawning processes can block the main thread for a few ms. However we didn't try to dig further into why spawning conda was blocking for a few seconds, primarily because the suggestion was not being actively worked on back then
Performance issue filled for other cases here: https://github.com/microsoft/vscode/issues/198384
Yeah a few ms is expected, but it's very different from over 2 seconds which is what the first spawn takes in my screenshot.
@Tyriar not sure but having some basic data points from @karrtikr I feel there is a binary scanning delaying the spawn call. @karrtikr can you collect an event trace following the steps below.
Windows Performance Recorder
from system start menuI've shared the event trace via email.
@karrtikr thanks for the trace, I looked into it and found it to be unusual, the uv_spawn
(equivalent of child_process.spawn) call in question shows a wait time of 2.7s but the interesting bit is that wait is on the thread performing v8 cpu profiling, not what I had expected.
Can you provide me another windows event trace of the slow conda or win reg or git spawn calls but this time don't invoke the v8 cpu profiler. I am curious to see how the trace comes out without any node inspector involved.
@deepak1556 Could this be related https://github.com/nodejs/node/issues/14917
Similar finding in the above issue as well, (related to git exe in VS Code https://github.com/microsoft/vscode/issues/71290) @bpasero @lszomoru /cc
Issue is unrelated to the node.js issue, it is specific to fork syscall on linux impacted with v8 heap regions which is already fixed in upstream and also fixed in our stable versions for a while now. I haven't seen similar issues for windows and the current data is still too early to conclude.
Shared the event trace again.
I'm assuming by v8 cpu profiling you meant the Flame Chart Visualizer for JavaScript Profiles
extension I had been using. This time I do not attach it, but I'm still debugging the extension, so the node debugger was still attached.
@karrtikr thanks for new traces, I looked at them today and this is better than the first trace. Compiling the findings below,
Process id (21040) refers to the extension host in the below screenshots
uv_spawn
call that starts at 8.4s and ends at 11.9s corresponding to the above launch. Basically there was a wait time of ~3s to complete the spawn call.MsMPEng.exe
with process id 6724 and thread id 11092. The process belongs to MS defender and the relevant stack shows something related to realtime scanning as seen in the screenshot belowGiven it looks like it's related to defender, consider not doing a large change like moving parts to workers. This will complicate things significantly but not help many users as in the past most defender problems like this are mainly restricted to MS employees and those without properly configured defender. There are some things you can try to make defender play nicer like ensuring your Dev folder(s) are excluded from scanning, using Dev drives, etc.
It doesn't look like I have access to disable real time scanning as it's controlled by the admin, but I added the folder containing the problematic binary conda
to exclusions list:
Unfortunately it doesn't seem to help, as you can see in the following screenshot it still takes 3 seconds:
Let me know if any other information is required.
Sent a mail to MS defender mailing list, lets wait for the response before proceeding further.
@karrtikr the affected machine OS version is quite old and unsupported, defender team has requested to get trace after updating the machine to latest stable windows,
The collected traces are from a machine running an old insiders build from 2021/12/03 (22518.1000.amd64fre.rs_prerelease.211203-1458) which is unsupported and for which symbols are no longer available.
Please try the following next steps,
1) Update OS to latest stable or insider windows 2) If the issue still repros, let's sync up. I will help you in collecting the required traces (steps are different than before)
@karrtikr did you have a chance to try the above steps ?
@deepak1556
It seems to be much better! It occasionally goes up to 200-250ms but not more.
We launch a lot of binaries though, so overall it still blocks a few seconds in accumulation.
Numbers do look reasonable, however I am curious about the >150ms ones. For the registry operations, I see that you are using https://www.npmjs.com/package/winreg which basically does spawn calls using reg binaries not the best way to do it given the number of queries I see in the screenshot. Have you considered using a native module performing the relevant registry syscalls ? For VSCode core, we use https://github.com/microsoft/vscode-windows-registry it only exposes a getter api but we can add additional api as needed.
however I am curious about the >150ms ones
Okk, let me know if I should still get the trace for it. It might just be the heavy load on the machine due to so many spawn calls.
Have you considered using a native module performing the relevant registry syscalls ? For VSCode core, we use https://github.com/microsoft/vscode-windows-registry it only exposes a getter api but we can add additional api as needed.
Interesting, we can definitely have a look. Although > 150ms still happens for conda.
Can you isolate the conda spawn calls into a minimal script, I want to compare the times between Node.js and VSCode.
Sorry for the delayed response, missed the notification due to holidays, let me know if you still need the info. Closing this issue as experiment is ready to be rolled out, and we can look into further investigating it based on experiments results.
If you can provide sample for https://github.com/microsoft/vscode-python/issues/22146#issuecomment-1857324356 we can investigate the > 150ms
calls.
Hi @karrtikr, is this issue verifiable?
Python: Select interpreter
and capture the first few interpreters in the list, we're going to verify this later"python.experiments.optInto": [
"pythonDiscoveryUsingWorkers"
]
Python: Clear cache and reload window
commandPython: Select interpreter
I have some weird behavior. I have before:
And after
For some reason, the condaenv
is repeated after.
@karrtikr I think, the verification steps should indicate the fact that this needs to be tested on Windows with Conda. as this is a fix primarily for Windows users.
Coincidentally, I was on windows with conda installed with the above issue
Hi @karrtikr I am pinging about the milestone on this issue. We have branched off to the release
branch recently. Would you like to make this issue a candidate or move it to the March 2024
milestone?
Hi I haven't gotten to it yet, hence moved it to March thanks.
@andreamah I've prepared a fix which very likely fixes the issue, please give it a try when you can: https://github.com/microsoft/vscode-python/actions/runs/8045205090/artifacts/1274325464. You can use Extension: Install from VSIX
command to install it.
Make sure run Python: Clear cache and reload window
command.
@andreamah Fix should be out in the pre-release version of the extension.
Verification steps: https://github.com/microsoft/vscode-python/issues/22146#issuecomment-1953653626
This failed verification for me, the output shows the worker option is active, but there's an exception launching conda (which I don't think is installed) and there's no "worker id":
2024-03-25 12:03:15.411 [info] Experiment 'pythonRecommendTensorboardExt' is active
2024-03-25 12:03:15.411 [info] Experiment 'pythonREPLSmartSend' is active
2024-03-25 12:03:15.411 [info] Experiment 'pythonTerminalEnvVarActivation' is active
2024-03-25 12:03:15.411 [info] Experiment 'pythonTestAdapter' is active
2024-03-25 12:03:15.411 [info] Default formatter is set to null for workspace /Users/tyriar/playground/hatch
2024-03-25 12:03:15.411 [info] Test server listening.
2024-03-25 12:03:15.411 [info] Python interpreter path: ~/Library/Application Support/hatch/env/virtual/testproj/7Y1g8kEb/testproj/bin/python
2024-03-25 12:03:16.023 [info] > . "~/Library/Application Support/hatch/env/virtual/testproj/7Y1g8kEb/testproj/bin/activate" && echo 'e8b39361-0157-4923-80e1-22d70d46dee6' && python ~/.vscode-insiders/extensions/ms-python.python-2024.3.10851013/python_files/printEnvVariables.py
2024-03-25 12:03:16.023 [info] shell: bash
2024-03-25 12:03:16.129 [info] > /opt/homebrew/bin/python3.10 ~/.vscode-insiders/extensions/ms-python.python-2024.3.10851013/python_files/printEnvVariables.py
2024-03-25 12:03:16.129 [info] shell: bash
2024-03-25 12:03:16.423 [info] Setting environment variable VIRTUAL_ENV in collection to /Users/tyriar/Library/Application Support/hatch/env/virtual/testproj/7Y1g8kEb/testproj {"applyAtShellIntegration":true,"applyAtProcessCreation":true}
2024-03-25 12:03:16.423 [info] Prepending environment variable PATH in collection with /Users/tyriar/.vscode-insiders/extensions/ms-python.python-2024.3.10851013/python_files/deactivate/bash:/Users/tyriar/Library/Application Support/hatch/env/virtual/testproj/7Y1g8kEb/testproj/bin: {"applyAtShellIntegration":true,"applyAtProcessCreation":true}
2024-03-25 12:03:16.423 [info] Prepending environment variable PS1 in collection with (testproj) {"applyAtShellIntegration":true,"applyAtProcessCreation":false}
2024-03-25 12:03:16.423 [info] Setting environment variable XPC_SERVICE_NAME in collection to 0 {"applyAtShellIntegration":true,"applyAtProcessCreation":true}
2024-03-25 12:03:16.423 [info] Setting environment variable VIRTUAL_ENV_PROMPT in collection to testproj {"applyAtShellIntegration":true,"applyAtProcessCreation":true}
2024-03-25 12:03:16.424 [info] Send text to terminal: /opt/homebrew/bin/python3.10 /Users/tyriar/.vscode-insiders/extensions/ms-python.python-2024.3.10851013/python_files/printEnvVariablesToFile.py /Users/tyriar/.vscode-insiders/extensions/ms-python.python-2024.3.10851013/python_files/deactivate/bash/envVars.txt
2024-03-25 12:03:17.139 [info] Starting Pylance language server.
2024-03-25 12:03:26.163 [info] Discover tests for workspace name: undefined - uri: /Users/tyriar/Library/Application Support/Code - Insiders/User/settings.json
2024-03-25 12:04:12.023 [info] Experiment 'pythonDiscoveryUsingWorkers' is active
2024-03-25 12:04:12.023 [info] Experiment 'pythonRecommendTensorboardExt' is active
2024-03-25 12:04:12.023 [info] Experiment 'pythonREPLSmartSend' is active
2024-03-25 12:04:12.023 [info] Experiment 'pythonTerminalEnvVarActivation' is active
2024-03-25 12:04:12.023 [info] Experiment 'pythonTestAdapter' is active
2024-03-25 12:04:12.023 [debug] Start watching file for changes /Users/tyriar/.conda/environments.txt
2024-03-25 12:04:12.023 [debug] Start watching: /Users/tyriar/.conda with pattern environments.txt using VSCode API
2024-03-25 12:04:12.023 [debug] Start watching root /Users/tyriar/playground/hatch for globs ["python","*/python","*/bin/python"]
2024-03-25 12:04:12.023 [debug] Start watching: /Users/tyriar/playground/hatch with pattern python using VSCode API
2024-03-25 12:04:12.023 [debug] Start watching: /Users/tyriar/playground/hatch with pattern */python using VSCode API
2024-03-25 12:04:12.023 [debug] Start watching: /Users/tyriar/playground/hatch with pattern */bin/python using VSCode API
2024-03-25 12:04:12.023 [info] Default formatter is set to null for workspace /Users/tyriar/playground/hatch
2024-03-25 12:04:12.023 [debug] Waiting for test server to start...
2024-03-25 12:04:12.023 [debug] Searching for interpreters in posix paths locator
2024-03-25 12:04:12.023 [debug] Searching for pyenv environments
2024-03-25 12:04:12.023 [debug] Searching for conda.
2024-03-25 12:04:12.023 [debug] Probing conda binary: conda
2024-03-25 12:04:12.023 [debug] Searching for custom workspace envs
2024-03-25 12:04:12.023 [debug] Probing Hatch binary hatch
2024-03-25 12:04:12.023 [info] Test server listening.
2024-03-25 12:04:12.023 [debug] Test server started.
2024-03-25 12:04:12.023 [debug] Testing: Setting up watcher for /Users/tyriar/playground/hatch
2024-03-25 12:04:12.023 [debug] Finished searching for custom virtual envs
2024-03-25 12:04:12.023 [debug] Couldn't locate the state binary.
2024-03-25 12:04:12.023 [debug] Dump environment variables {
"COMMAND_MODE": "unix2003",
"HOME": "/Users/tyriar",
"HOMEBREW_CELLAR": "/opt/homebrew/Cellar",
"HOMEBREW_PREFIX": "/opt/homebrew",
"HOMEBREW_REPOSITORY": "/opt/homebrew",
"INFOPATH": "/opt/homebrew/share/info:",
"LESS": "-R",
"LOGNAME": "tyriar",
"LSCOLORS": "Gxfxcxdxbxegedabagacad",
"LS_COLORS": "di=1;36:ln=35:so=32:pi=33:ex=31:bd=34;46:cd=34;43:su=30;41:sg=30;46:tw=30;42:ow=30;43",
"MANPATH": "/opt/homebrew/share/man::",
"MallocNanoZone": "0",
"OLDPWD": "/",
"ORIGINAL_XDG_CURRENT_DESKTOP": "undefined",
"PAGER": "less",
"PWD": "/",
"SHELL": "/bin/zsh",
"SHLVL": "0",
"SSH_AUTH_SOCK": "/private/tmp/com.apple.launchd.1Yc7IXFDGh/Listeners",
"TMPDIR": "/var/folders/nk/960h1fp91k3gpt8_70qg5j0h0000gn/T/",
"USER": "tyriar",
"VSCODE_AMD_ENTRYPOINT": "vs/workbench/api/node/extensionHostProcess",
"VSCODE_CODE_CACHE_PATH": "/Users/tyriar/Library/Application Support/Code - Insiders/CachedData/b0d975fc6370f15570c380f41015b1ca2cdcb791",
"VSCODE_CRASH_REPORTER_PROCESS_TYPE": "extensionHost",
"VSCODE_CWD": "/",
"VSCODE_HANDLES_UNCAUGHT_ERRORS": "true",
"VSCODE_IPC_HOOK": "/Users/tyriar/Library/Application Support/Code - Insiders/1.88-main.sock",
"VSCODE_NLS_CONFIG": "{\"locale\":\"en\",\"osLocale\":\"en-au\",\"availableLanguages\":{},\"_languagePackSupport\":true}",
"VSCODE_PID": "15475",
"XPC_FLAGS": "0x0",
"XPC_SERVICE_NAME": "application.com.microsoft.VSCodeInsiders.13688824.13688831",
"ZSH": "/Users/tyriar/.oh-my-zsh",
"_": "/Applications/Visual Studio Code - Insiders.app/Contents/MacOS/Electron",
"__CFBundleIdentifier": "com.microsoft.VSCodeInsiders",
"__CF_USER_TEXT_ENCODING": "0x1F5:0x0:0xF",
"ELECTRON_RUN_AS_NODE": "1",
"VSCODE_L10N_BUNDLE_LOCATION": "",
"PATH": "/Library/Frameworks/Python.framework/Versions/3.12/bin:/opt/homebrew/bin:/opt/homebrew/sbin:/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"
}
2024-03-25 12:04:12.023 [info] > conda info --json
2024-03-25 12:04:12.023 [debug] Failed to spawn conda binary conda [Error: spawn conda ENOENT
at ChildProcess._handle.onexit (node:internal/child_process:284:19)
at onErrorNT (node:internal/child_process:477:16)
at process.processTicksAndRejections (node:internal/process/task_queues:82:21)] {
errno: -2,
code: 'ENOENT',
syscall: 'spawn conda',
path: 'conda',
spawnargs: [ 'info', '--json' ]
}
2024-03-25 12:04:12.023 [debug] Searching for workspace virtual envs in: /Users/tyriar/playground/hatch
2024-03-25 12:04:12.023 [debug] Dump environment variables {
"COMMAND_MODE": "unix2003",
"HOME": "/Users/tyriar",
"HOMEBREW_CELLAR": "/opt/homebrew/Cellar",
"HOMEBREW_PREFIX": "/opt/homebrew",
"HOMEBREW_REPOSITORY": "/opt/homebrew",
"INFOPATH": "/opt/homebrew/share/info:",
"LESS": "-R",
"LOGNAME": "tyriar",
"LSCOLORS": "Gxfxcxdxbxegedabagacad",
"LS_COLORS": "di=1;36:ln=35:so=32:pi=33:ex=31:bd=34;46:cd=34;43:su=30;41:sg=30;46:tw=30;42:ow=30;43",
"MANPATH": "/opt/homebrew/share/man::",
"MallocNanoZone": "0",
"OLDPWD": "/",
"ORIGINAL_XDG_CURRENT_DESKTOP": "undefined",
"PAGER": "less",
"PWD": "/",
"SHELL": "/bin/zsh",
"SHLVL": "0",
"SSH_AUTH_SOCK": "/private/tmp/com.apple.launchd.1Yc7IXFDGh/Listeners",
"TMPDIR": "/var/folders/nk/960h1fp91k3gpt8_70qg5j0h0000gn/T/",
"USER": "tyriar",
"VSCODE_AMD_ENTRYPOINT": "vs/workbench/api/node/extensionHostProcess",
"VSCODE_CODE_CACHE_PATH": "/Users/tyriar/Library/Application Support/Code - Insiders/CachedData/b0d975fc6370f15570c380f41015b1ca2cdcb791",
"VSCODE_CRASH_REPORTER_PROCESS_TYPE": "extensionHost",
"VSCODE_CWD": "/",
"VSCODE_HANDLES_UNCAUGHT_ERRORS": "true",
"VSCODE_IPC_HOOK": "/Users/tyriar/Library/Application Support/Code - Insiders/1.88-main.sock",
"VSCODE_NLS_CONFIG": "{\"locale\":\"en\",\"osLocale\":\"en-au\",\"availableLanguages\":{},\"_languagePackSupport\":true}",
"VSCODE_PID": "15475",
"XPC_FLAGS": "0x0",
"XPC_SERVICE_NAME": "application.com.microsoft.VSCodeInsiders.13688824.13688831",
"ZSH": "/Users/tyriar/.oh-my-zsh",
"_": "/Applications/Visual Studio Code - Insiders.app/Contents/MacOS/Electron",
"__CFBundleIdentifier": "com.microsoft.VSCodeInsiders",
"__CF_USER_TEXT_ENCODING": "0x1F5:0x0:0xF",
"ELECTRON_RUN_AS_NODE": "1",
"VSCODE_L10N_BUNDLE_LOCATION": "",
"PATH": "/Library/Frameworks/Python.framework/Versions/3.12/bin:/opt/homebrew/bin:/opt/homebrew/sbin:/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"
}
2024-03-25 12:04:12.023 [info] > hatch env show --json
2024-03-25 12:04:12.023 [info] cwd: .
2024-03-25 12:04:12.023 [debug] [Error: spawn hatch ENOENT
at ChildProcess._handle.onexit (node:internal/child_process:284:19)
at onErrorNT (node:internal/child_process:477:16)
at process.processTicksAndRejections (node:internal/process/task_queues:82:21)] {
errno: -2,
code: 'ENOENT',
syscall: 'spawn hatch',
path: 'hatch',
spawnargs: [ 'env', 'show', '--json' ]
}
2024-03-25 12:04:12.023 [debug] Failed to find Hatch binary hatch
2024-03-25 12:04:12.023 [debug] No Hatch binary found
2024-03-25 12:04:12.023 [debug] Finished searching for Hatch envs
2024-03-25 12:04:12.026 [debug] Finished searching for global virtual envs
2024-03-25 12:04:12.026 [debug] Finished searching for workspace virtual envs
2024-03-25 12:04:12.033 [debug] Finished searching for poetry envs
2024-03-25 12:04:12.041 [debug] Attempting to resolve symbolic link: /usr/bin/python3
2024-03-25 12:04:12.042 [info] Found: /usr/bin/python3 --> /usr/bin/python3
2024-03-25 12:04:12.045 [debug] Couldn't locate the conda binary.
2024-03-25 12:04:12.045 [debug] Couldn't locate the conda binary.
2024-03-25 12:04:12.056 [debug] Attempting to resolve symbolic link: /usr/local/bin/python3
2024-03-25 12:04:12.056 [info] Found: /usr/local/bin/python3 --> /Library/Frameworks/Python.framework/Versions/3.12/bin/python3.12
2024-03-25 12:04:12.056 [debug] Attempting to resolve symbolic link: /usr/local/bin/python3.12
2024-03-25 12:04:12.057 [info] Found: /usr/local/bin/python3.12 --> /Library/Frameworks/Python.framework/Versions/3.12/bin/python3.12
2024-03-25 12:04:12.087 [debug] Attempting to resolve symbolic link: /Library/Frameworks/Python.framework/Versions/3.12/bin/python3
2024-03-25 12:04:12.087 [info] Found: /Library/Frameworks/Python.framework/Versions/3.12/bin/python3 --> /Library/Frameworks/Python.framework/Versions/3.12/bin/python3.12
2024-03-25 12:04:12.087 [debug] Attempting to resolve symbolic link: /Library/Frameworks/Python.framework/Versions/3.12/bin/python3.12
2024-03-25 12:04:12.087 [info] Found: /Library/Frameworks/Python.framework/Versions/3.12/bin/python3.12 --> /Library/Frameworks/Python.framework/Versions/3.12/bin/python3.12
2024-03-25 12:04:12.087 [debug] Attempting to resolve symbolic link: /opt/homebrew/bin/python3.10
2024-03-25 12:04:12.088 [info] Found: /opt/homebrew/bin/python3.10 --> /opt/homebrew/Cellar/python@3.10/3.10.14/Frameworks/Python.framework/Versions/3.10/bin/python3.10
2024-03-25 12:04:12.088 [debug] Attempting to resolve symbolic link: /opt/homebrew/bin/python3.11
2024-03-25 12:04:12.088 [info] Found: /opt/homebrew/bin/python3.11 --> /opt/homebrew/Cellar/python@3.11/3.11.8/Frameworks/Python.framework/Versions/3.11/bin/python3.11
2024-03-25 12:04:12.090 [debug] Found 4 python binaries in posix paths
2024-03-25 12:04:12.111 [debug] Python API env change detected /usr/bin/python3 add
2024-03-25 12:04:12.111 [info] > /usr/bin/python3 -I ~/.vscode-insiders/extensions/ms-python.python-2024.3.10851013/python_files/get_output_via_markers.py ~/.vscode-insiders/extensions/ms-python.python-2024.3.10851013/python_files/interpreterInfo.py
2024-03-25 12:04:12.113 [debug] Python API env change detected /usr/local/bin/python3 add
2024-03-25 12:04:12.113 [info] > /usr/local/bin/python3 -I ~/.vscode-insiders/extensions/ms-python.python-2024.3.10851013/python_files/get_output_via_markers.py ~/.vscode-insiders/extensions/ms-python.python-2024.3.10851013/python_files/interpreterInfo.py
2024-03-25 12:04:12.115 [debug] Python API env change detected /opt/homebrew/bin/python3.10 add
2024-03-25 12:04:12.115 [debug] Finished searching for interpreters in posix paths locator
2024-03-25 12:04:12.116 [debug] Python API env change detected /opt/homebrew/bin/python3.11 add
2024-03-25 12:04:12.116 [debug] Finished with environment reducer
2024-03-25 12:04:12.116 [debug] No cached env found for /opt/homebrew/bin/python3.11
2024-03-25 12:04:12.116 [debug] No cached env found for /opt/homebrew/bin/python3.11
2024-03-25 12:04:12.319 [debug] Received shell integration sequence for bash
2024-03-25 12:04:12.325 [debug] Found interpreter for >> /usr/local/bin/python3 -I /Users/tyriar/.vscode-insiders/extensions/ms-python.python-2024.3.10851013/python_files/get_output_via_markers.py /Users/tyriar/.vscode-insiders/extensions/ms-python.python-2024.3.10851013/python_files/interpreterInfo.py <<: {"versionInfo":[3,12,0,"final",0],"sysPrefix":"/Library/Frameworks/Python.framework/Versions/3.12","sysVersion":"3.12.0 (v3.12.0:0fb18b02c8, Oct 2 2023, 09:45:56) [Clang 13.0.0 (clang-1300.0.29.30)]","is64Bit":true}
2024-03-25 12:04:12.326 [info] > /opt/homebrew/bin/python3.10 -I ~/.vscode-insiders/extensions/ms-python.python-2024.3.10851013/python_files/get_output_via_markers.py ~/.vscode-insiders/extensions/ms-python.python-2024.3.10851013/python_files/interpreterInfo.py
2024-03-25 12:04:12.326 [debug] Python API env change detected /usr/local/bin/python3 update
2024-03-25 12:04:12.481 [debug] Found interpreter for >> /usr/bin/python3 -I /Users/tyriar/.vscode-insiders/extensions/ms-python.python-2024.3.10851013/python_files/get_output_via_markers.py /Users/tyriar/.vscode-insiders/extensions/ms-python.python-2024.3.10851013/python_files/interpreterInfo.py <<: {"versionInfo":[3,9,6,"final",0],"sysPrefix":"/Library/Developer/CommandLineTools/Library/Frameworks/Python3.framework/Versions/3.9","sysVersion":"3.9.6 (default, Feb 3 2024, 15:58:27) \n[Clang 15.0.0 (clang-1500.3.9.4)]","is64Bit":true}
2024-03-25 12:04:12.482 [info] > /opt/homebrew/bin/python3.11 -I ~/.vscode-insiders/extensions/ms-python.python-2024.3.10851013/python_files/get_output_via_markers.py ~/.vscode-insiders/extensions/ms-python.python-2024.3.10851013/python_files/interpreterInfo.py
2024-03-25 12:04:12.482 [debug] Python API env change detected /usr/bin/python3 update
2024-03-25 12:04:12.482 [debug] Found interpreter for >> /opt/homebrew/bin/python3.10 -I /Users/tyriar/.vscode-insiders/extensions/ms-python.python-2024.3.10851013/python_files/get_output_via_markers.py /Users/tyriar/.vscode-insiders/extensions/ms-python.python-2024.3.10851013/python_files/interpreterInfo.py <<: {"versionInfo":[3,10,14,"final",0],"sysPrefix":"/opt/homebrew/opt/python@3.10/Frameworks/Python.framework/Versions/3.10","sysVersion":"3.10.14 (main, Mar 19 2024, 21:46:16) [Clang 15.0.0 (clang-1500.3.9.4)]","is64Bit":true}
2024-03-25 12:04:12.482 [debug] Python API env change detected /opt/homebrew/bin/python3.10 update
2024-03-25 12:04:12.652 [debug] Found interpreter for >> /opt/homebrew/bin/python3.11 -I /Users/tyriar/.vscode-insiders/extensions/ms-python.python-2024.3.10851013/python_files/get_output_via_markers.py /Users/tyriar/.vscode-insiders/extensions/ms-python.python-2024.3.10851013/python_files/interpreterInfo.py <<: {"versionInfo":[3,11,8,"final",0],"sysPrefix":"/opt/homebrew/opt/python@3.11/Frameworks/Python.framework/Versions/3.11","sysVersion":"3.11.8 (main, Feb 6 2024, 21:21:21) [Clang 15.0.0 (clang-1500.1.0.2.5)]","is64Bit":true}
2024-03-25 12:04:12.652 [debug] Python API env change detected /opt/homebrew/bin/python3.11 update
2024-03-25 12:04:12.652 [debug] Finished with environment resolver
2024-03-25 12:04:12.652 [debug] Environment resolver resolved /opt/homebrew/bin/python3.11 for {"name":"","location":"","kind":"global-other","executable":{"filename":"/opt/homebrew/bin/python3.11","sysPrefix":"","ctime":1710439746947,"mtime":1710439746947},"display":"Python 3.11.x","version":{"major":3,"minor":11,"micro":-1},"arch":1,"distro":{"org":""},"source":[],"id":"/opt/homebrew/bin/python3.11","detailedDisplayName":"Python 3.11.x"} to {"arch":3,"executable":{"filename":"/opt/homebrew/bin/python3.11","sysPrefix":"/opt/homebrew/opt/python@3.11/Frameworks/Python.framework/Versions/3.11","mtime":-1,"ctime":-1},"version":{"major":3,"minor":11,"micro":8,"release":{"level":"final","serial":0},"sysVersion":"3.11.8 (main, Feb 6 2024, 21:21:21) [Clang 15.0.0 (clang-1500.1.0.2.5)]"}}
2024-03-25 12:04:12.652 [debug] Environment resolver resolved /opt/homebrew/bin/python3.11 for {"name":"","location":"","kind":"global-other","executable":{"filename":"/opt/homebrew/bin/python3.11","sysPrefix":"","ctime":1710439746947,"mtime":1710439746947},"display":"Python 3.11.x","version":{"major":3,"minor":11,"micro":-1},"arch":1,"distro":{"org":""},"source":[],"id":"/opt/homebrew/bin/python3.11","detailedDisplayName":"Python 3.11.x"} to {"arch":3,"executable":{"filename":"/opt/homebrew/bin/python3.11","sysPrefix":"/opt/homebrew/opt/python@3.11/Frameworks/Python.framework/Versions/3.11","mtime":-1,"ctime":-1},"version":{"major":3,"minor":11,"micro":8,"release":{"level":"final","serial":0},"sysVersion":"3.11.8 (main, Feb 6 2024, 21:21:21) [Clang 15.0.0 (clang-1500.1.0.2.5)]"}}
2024-03-25 12:04:12.652 [debug] Resolved /opt/homebrew/bin/python3.11 using downstream locator
2024-03-25 12:04:12.652 [debug] Python API env change detected /opt/homebrew/bin/python3.11 update
2024-03-25 12:04:12.652 [debug] Flushing env to cache /opt/homebrew/bin/python3.11
2024-03-25 12:04:12.652 [debug] Resolved /opt/homebrew/bin/python3.11 using downstream locator
2024-03-25 12:04:12.652 [debug] Flushing env to cache /opt/homebrew/bin/python3.11
2024-03-25 12:04:12.654 [debug] Python API env change detected /opt/homebrew/bin/python3.11 update
2024-03-25 12:04:12.655 [debug] Environments added to cache [{"name":"","location":"","kind":"global-other","executable":{"filename":"/usr/bin/python3","sysPrefix":"/Library/Developer/CommandLineTools/Library/Frameworks/Python3.framework/Versions/3.9","ctime":1709179520000,"mtime":1709179520000},"display":"Python 3.9.6 64-bit","version":{"major":3,"minor":9,"micro":6,"release":{"level":"final","serial":0},"sysVersion":"3.9.6 (default, Feb 3 2024, 15:58:27) \n[Clang 15.0.0 (clang-1500.3.9.4)]"},"arch":3,"distro":{"org":""},"source":["path env var"],"id":"/usr/bin/python3","detailedDisplayName":"Python 3.9.6 64-bit"},{"name":"","location":"","kind":"global-other","executable":{"filename":"/usr/local/bin/python3","sysPrefix":"/Library/Frameworks/Python.framework/Versions/3.12","ctime":1697737730581,"mtime":1697737729896},"display":"Python 3.12.0 64-bit","version":{"major":3,"minor":12,"micro":0,"release":{"level":"final","serial":0},"sysVersion":"3.12.0 (v3.12.0:0fb18b02c8, Oct 2 2023, 09:45:56) [Clang 13.0.0 (clang-1300.0.29.30)]"},"arch":3,"distro":{"org":""},"source":["path env var"],"id":"/usr/local/bin/python3","detailedDisplayName":"Python 3.12.0 64-bit"},{"name":"","location":"","kind":"global-other","executable":{"filename":"/opt/homebrew/bin/python3.10","sysPrefix":"/opt/homebrew/opt/python@3.10/Frameworks/Python.framework/Versions/3.10","ctime":1711280066232,"mtime":1711280066232},"display":"Python 3.10.14 64-bit","version":{"major":3,"minor":10,"micro":14,"release":{"level":"final","serial":0},"sysVersion":"3.10.14 (main, Mar 19 2024, 21:46:16) [Clang 15.0.0 (clang-1500.3.9.4)]"},"arch":3,"distro":{"org":""},"source":["path env var"],"id":"/opt/homebrew/bin/python3.10","detailedDisplayName":"Python 3.10.14 64-bit"},{"name":"","location":"","kind":"global-other","executable":{"filename":"/opt/homebrew/bin/python3.11","sysPrefix":"/opt/homebrew/opt/python@3.11/Frameworks/Python.framework/Versions/3.11","ctime":1710439746947,"mtime":1710439746947},"display":"Python 3.11.8 64-bit","version":{"major":3,"minor":11,"micro":8,"release":{"level":"final","serial":0},"sysVersion":"3.11.8 (main, Feb 6 2024, 21:21:21) [Clang 15.0.0 (clang-1500.1.0.2.5)]"},"arch":3,"distro":{"org":""},"source":["path env var"],"id":"/opt/homebrew/bin/python3.11","detailedDisplayName":"Python 3.11.8 64-bit"}]
2024-03-25 12:04:12.655 [debug] Dump environment variables {
"COMMAND_MODE": "unix2003",
"HOME": "/Users/tyriar",
"HOMEBREW_CELLAR": "/opt/homebrew/Cellar",
"HOMEBREW_PREFIX": "/opt/homebrew",
"HOMEBREW_REPOSITORY": "/opt/homebrew",
"INFOPATH": "/opt/homebrew/share/info:",
"LESS": "-R",
"LOGNAME": "tyriar",
"LSCOLORS": "Gxfxcxdxbxegedabagacad",
"LS_COLORS": "di=1;36:ln=35:so=32:pi=33:ex=31:bd=34;46:cd=34;43:su=30;41:sg=30;46:tw=30;42:ow=30;43",
"MANPATH": "/opt/homebrew/share/man::",
"MallocNanoZone": "0",
"OLDPWD": "/",
"ORIGINAL_XDG_CURRENT_DESKTOP": "undefined",
"PAGER": "less",
"PWD": "/",
"SHELL": "/bin/zsh",
"SHLVL": "0",
"SSH_AUTH_SOCK": "/private/tmp/com.apple.launchd.1Yc7IXFDGh/Listeners",
"TMPDIR": "/var/folders/nk/960h1fp91k3gpt8_70qg5j0h0000gn/T/",
"USER": "tyriar",
"VSCODE_AMD_ENTRYPOINT": "vs/workbench/api/node/extensionHostProcess",
"VSCODE_CODE_CACHE_PATH": "/Users/tyriar/Library/Application Support/Code - Insiders/CachedData/b0d975fc6370f15570c380f41015b1ca2cdcb791",
"VSCODE_CRASH_REPORTER_PROCESS_TYPE": "extensionHost",
"VSCODE_CWD": "/",
"VSCODE_HANDLES_UNCAUGHT_ERRORS": "true",
"VSCODE_IPC_HOOK": "/Users/tyriar/Library/Application Support/Code - Insiders/1.88-main.sock",
"VSCODE_NLS_CONFIG": "{\"locale\":\"en\",\"osLocale\":\"en-au\",\"availableLanguages\":{},\"_languagePackSupport\":true}",
"VSCODE_PID": "15475",
"XPC_FLAGS": "0x0",
"XPC_SERVICE_NAME": "application.com.microsoft.VSCodeInsiders.13688824.13688831",
"ZSH": "/Users/tyriar/.oh-my-zsh",
"_": "/Applications/Visual Studio Code - Insiders.app/Contents/MacOS/Electron",
"__CFBundleIdentifier": "com.microsoft.VSCodeInsiders",
"__CF_USER_TEXT_ENCODING": "0x1F5:0x0:0xF",
"ELECTRON_RUN_AS_NODE": "1",
"VSCODE_L10N_BUNDLE_LOCATION": "",
"PATH": "/Library/Frameworks/Python.framework/Versions/3.12/bin:/opt/homebrew/bin:/opt/homebrew/sbin:/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"
}
2024-03-25 12:04:12.656 [debug] Did we determine shell integration to be working for bash ? true
2024-03-25 12:04:12.656 [debug] Found cached env for /opt/homebrew/bin/python3.11
2024-03-25 12:04:12.656 [debug] Found cached env for /opt/homebrew/bin/python3.11
2024-03-25 12:04:12.657 [debug] Found cached env for /opt/homebrew/bin/python3.11
2024-03-25 12:04:12.657 [info] Python interpreter path: /opt/homebrew/bin/python3.11
2024-03-25 12:04:12.657 [debug] Found cached env for /opt/homebrew/bin/python3.11
2024-03-25 12:04:12.774 [debug] Found cached env for /opt/homebrew/bin/python3.11
2024-03-25 12:04:12.780 [debug] Activation Commands received undefined for shell /bin/bash, resource undefined and interpreter /opt/homebrew/bin/python3.11
2024-03-25 12:04:12.780 [debug] Activated environment variables for undefined undefined
2024-03-25 12:04:12.796 [debug] Extension ms-python.vscode-pylance accessed onDidChangeActiveEnvironmentPath with args: undefined
2024-03-25 12:04:12.797 [debug] Extension ms-python.vscode-pylance accessed onDidEnvironmentVariablesChange with args: undefined
2024-03-25 12:04:13.599 [info] Starting Pylance language server.
2024-03-25 12:04:13.599 [debug] Found cached env for /opt/homebrew/bin/python3.11
2024-03-25 12:04:13.602 [debug] Found cached env for /opt/homebrew/bin/python3.11
2024-03-25 12:04:13.602 [debug] Found cached env for /opt/homebrew/bin/python3.11
2024-03-25 12:04:13.603 [debug] Extension ms-python.vscode-pylance accessed getEnvironmentVariables with args: undefined
2024-03-25 12:04:13.604 [debug] Extension ms-python.vscode-pylance accessed getActiveEnvironmentPath with args: undefined
2024-03-25 12:04:13.604 [debug] Extension ms-python.vscode-pylance accessed getActiveEnvironmentPath with args: undefined
2024-03-25 12:04:13.604 [debug] Extension ms-python.vscode-pylance accessed resolveEnvironment with args: {"id":"/opt/homebrew/bin/python3.11","path":"/opt/homebrew/bin/python3.11"}
2024-03-25 12:04:13.604 [debug] Extension ms-python.vscode-pylance accessed resolveEnvironment with args: {"id":"/opt/homebrew/bin/python3.11","path":"/opt/homebrew/bin/python3.11"}
2024-03-25 12:04:13.854 [debug] Delay Trigger[Test Configuration Change]: triggered=2, called=1
2024-03-25 12:04:18.014 [debug] Terminal shell path '/bin/bash' identified as shell 'bash'
2024-03-25 12:04:18.014 [debug] Shell identified as bash
2024-03-25 12:04:18.014 [debug] Found cached env for /opt/homebrew/bin/python3.11
2024-03-25 12:04:18.145 [debug] Found cached env for /opt/homebrew/bin/python3.11
2024-03-25 12:04:18.147 [debug] Found cached env for /opt/homebrew/bin/python3.11
2024-03-25 12:04:24.516 [debug] Found cached env for /opt/homebrew/bin/python3.11
2024-03-25 12:04:24.855 [debug] Found cached env for /opt/homebrew/bin/python3.11
but there's an exception launching conda (which I don't think is installed) and there's no "worker id"
Sorry, this is actually expected, missed to update the verification steps from before. The important thing to verify here is that the number of environments discovered are still the same, once discovery finishes in both cases.
https://github.com/microsoft/vscode-python/issues/21755
Spike results
Based on CPU profiles in https://github.com/microsoft/vscode-python/issues/21755#issuecomment-1730302574 discovery is mainly blocked by:
Note spawning python binaries is fine, it blocks very little of the time.