Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Pylance consumes 100-200% CPU and takes long time to process code with many layers of nested parentheses #2299

Closed
theJenix opened this issue Jan 27, 2022 · 11 comments
Labels
bug Something isn't working fixed in next version (main) A fix has been implemented and will appear in an upcoming version

Comments

@theJenix
Copy link

theJenix commented Jan 27, 2022

Environment data

  • Language Server version: 2022.1.4
  • OS and version: darwin arm64
  • Python version (and distribution if applicable, e.g. Anaconda): Python 3.9 (Homebrew)
  • python.analysis.indexing: null
  • python.analysis.typeCheckingMode: basic

Expected behaviour

When I make a change to a statement in a file, Pylance analyzes the file quickly (within a couple seconds max) and updates VSCode with the results.

Actual behaviour

When I change a specific statement with many layers of nested params (15 in the code below), Pylance takes >40 seconds to run per change, while still reporting the old error messages in VSCode. During this time, changes to other python files in the project are not error checked, and an Electron process is using 100-200% CPU time.

This will apparently stack up, e.g. if I make 2 changes to the statement, it will queue a second parse/analysis up to run after the first, which could lead to a scenario where it never (for all practical purposes) finishes.
XXX

Logs

Python Language Server Log

[Info  - 2:43:54 PM] (79364) Pylance language server 2022.1.4 (pyright 23b9c7e0) starting
[Info  - 2:43:54 PM] (79364) Server root directory: /Users/thejenix/.vscode/extensions/ms-python.vscode-pylance-2022.1.4/dist
[Info  - 2:43:54 PM] (79364) No configuration file found.
[Info  - 2:43:54 PM] (79364) No pyproject.toml file found.
[Info  - 2:43:54 PM] (79364) Setting pythonPath for service "test_proj": "/opt/homebrew/bin/python3"
[Warn  - 2:43:54 PM] (79364) stubPath /Users/thejenix/Development/src/xxx.io/addins/test_proj/typings is not a valid directory.
[Info  - 2:43:54 PM] (79364) Assuming Python version 3.9
[Info  - 2:43:54 PM] (79364) Assuming Python platform Darwin
[Info  - 2:43:54 PM] (79364) Search paths for /Users/thejenix/Development/src/xxx.io/addins/test_proj
[Info  - 2:43:54 PM] (79364)   /Users/thejenix/.vscode/extensions/ms-python.vscode-pylance-2022.1.4/dist/typeshed-fallback/stdlib
[Info  - 2:43:54 PM] (79364)   /Users/thejenix/Development/src/xxx.io/addins/test_proj
[Info  - 2:43:54 PM] (79364)   /Users/thejenix/Development/src/xxx.io/addins/test_proj/typings
[Info  - 2:43:54 PM] (79364)   /Users/thejenix/.vscode/extensions/ms-python.vscode-pylance-2022.1.4/dist/typeshed-fallback/stubs/...
[Info  - 2:43:54 PM] (79364)   /Users/thejenix/.vscode/extensions/ms-python.vscode-pylance-2022.1.4/dist/bundled/stubs
[Info  - 2:43:54 PM] (79364)   /opt/homebrew/Cellar/[email protected]/3.9.9/Frameworks/Python.framework/Versions/3.9/lib/python3.9
[Info  - 2:43:54 PM] (79364)   /opt/homebrew/Cellar/[email protected]/3.9.9/Frameworks/Python.framework/Versions/3.9/lib/python3.9/lib-dynload
[Info  - 2:43:54 PM] (79364)   /Users/thejenix/.local_arm64/lib/python/site-packages
[Info  - 2:43:54 PM] (79364)   /opt/homebrew/lib/python3.9/site-packages
[Info  - 2:43:54 PM] (79364) Adding fs watcher for library directories:
 /opt/homebrew/Cellar/[email protected]/3.9.9/Frameworks/Python.framework/Versions/3.9/lib/python3.9
/opt/homebrew/Cellar/[email protected]/3.9.9/Frameworks/Python.framework/Versions/3.9/lib/python3.9/lib-dynload
/Users/thejenix/.local_arm64/lib/python/site-packages
/opt/homebrew/lib/python3.9/site-packages
[Info  - 2:43:54 PM] (79364) Adding fs watcher for directories:
 /Users/thejenix/Development/src/xxx.io/addins/test_proj
[Info  - 2:43:54 PM] (79364) Searching for source files
[Info  - 2:43:54 PM] (79364) Found 1 source file
(79364) [FG] parsing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (40348ms)
[Info  - 2:44:35 PM] (79364) [FG] Long operation: parsing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (40348ms)
(79364) [FG] parsing: /Users/thejenix/.vscode/extensions/ms-python.vscode-pylance-2022.1.4/dist/typeshed-fallback/stdlib/builtins.pyi [fs read 1ms] (36ms)
(79364) [FG] binding: /Users/thejenix/.vscode/extensions/ms-python.vscode-pylance-2022.1.4/dist/typeshed-fallback/stdlib/builtins.pyi (16ms)
(79364) [FG] binding: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (1ms)
[Info  - 2:44:35 PM] (79364) Indexer background runner(2) root directory: /Users/thejenix/.vscode/extensions/ms-python.vscode-pylance-2022.1.4/dist (index)
[Info  - 2:44:35 PM] (79364) Indexing(2) started
(79364) [IDX(2)] index libraries /Users/thejenix/Development/src/xxx.io/addins/test_proj ...
(79364) [IDX(2)]   read stdlib indices (48ms)
(79364) [IDX(2)]   scan packages [found 16 modules over 1 exec env] (79ms)
(79364) [IDX(2)]   index execution environment /Users/thejenix/Development/src/xxx.io/addins/test_proj ...
(79364) [IDX(2)]     parsing: /opt/homebrew/Cellar/[email protected]/3.9.9/Frameworks/Python.framework/Versions/3.9/lib/python3.9/xml/__init__.py [fs read 0ms] (7ms)
(79364) [IDX(2)]     parsing: /Users/thejenix/.vscode/extensions/ms-python.vscode-pylance-2022.1.4/dist/typeshed-fallback/stdlib/builtins.pyi [fs read 2ms] (44ms)
(79364) [IDX(2)]     binding: /Users/thejenix/.vscode/extensions/ms-python.vscode-pylance-2022.1.4/dist/typeshed-fallback/stdlib/builtins.pyi (6ms)
(79364) [IDX(2)]     binding: /opt/homebrew/Cellar/[email protected]/3.9.9/Frameworks/Python.framework/Versions/3.9/lib/python3.9/xml/__init__.py (0ms)
(79364) [IDX(2)]     indexing: /opt/homebrew/Cellar/[email protected]/3.9.9/Frameworks/Python.framework/Versions/3.9/lib/python3.9/xml/__init__.py [found 0] (1ms)
(79364) [IDX(2)]     parsing: /Users/thejenix/.local_arm64/lib/python/site-packages/lazy_object_proxy/__init__.py [fs read 0ms] (4ms)
[Info  - 2:44:35 PM] (79364) Could not import 'copy_reg' in file '/Users/thejenix/.local_arm64/lib/python/site-packages/lazy_object_proxy/__init__.py'
[Info  - 2:44:35 PM] (79364)   Looking for typeshed stdlib path
[Info  - 2:44:35 PM] (79364)   Attempting to resolve using root path '/Users/thejenix/.vscode/extensions/ms-python.vscode-pylance-2022.1.4/dist/typeshed-fallback/stdlib'
[Info  - 2:44:35 PM] (79364)   Typeshed path not found
[Info  - 2:44:35 PM] (79364)   Looking in stubPath '/Users/thejenix/Development/src/xxx.io/addins/test_proj/typings'
[Info  - 2:44:35 PM] (79364)   Attempting to resolve stub package using root path '/Users/thejenix/Development/src/xxx.io/addins/test_proj/typings'
[Info  - 2:44:35 PM] (79364)   Attempting to resolve using root path '/Users/thejenix/Development/src/xxx.io/addins/test_proj/typings'
[Info  - 2:44:35 PM] (79364)   Looking in root directory of execution environment '/Users/thejenix/Development/src/xxx.io/addins/test_proj'
[Info  - 2:44:35 PM] (79364)   Attempting to resolve stub package using root path '/Users/thejenix/Development/src/xxx.io/addins/test_proj'
[Info  - 2:44:35 PM] (79364)   Attempting to resolve using root path '/Users/thejenix/Development/src/xxx.io/addins/test_proj'
[Info  - 2:44:35 PM] (79364)   Looking in python search path '/opt/homebrew/Cellar/[email protected]/3.9.9/Frameworks/Python.framework/Versions/3.9/lib/python3.9'
[Info  - 2:44:35 PM] (79364)   Attempting to resolve stub package using root path '/opt/homebrew/Cellar/[email protected]/3.9.9/Frameworks/Python.framework/Versions/3.9/lib/python3.9'
[Info  - 2:44:35 PM] (79364)   Attempting to resolve using root path '/opt/homebrew/Cellar/[email protected]/3.9.9/Frameworks/Python.framework/Versions/3.9/lib/python3.9'
[Info  - 2:44:35 PM] (79364)   Looking in python search path '/opt/homebrew/Cellar/[email protected]/3.9.9/Frameworks/Python.framework/Versions/3.9/lib/python3.9/lib-dynload'
[Info  - 2:44:35 PM] (79364)   Attempting to resolve stub package using root path '/opt/homebrew/Cellar/[email protected]/3.9.9/Frameworks/Python.framework/Versions/3.9/lib/python3.9/lib-dynload'
[Info  - 2:44:35 PM] (79364)   Attempting to resolve using root path '/opt/homebrew/Cellar/[email protected]/3.9.9/Frameworks/Python.framework/Versions/3.9/lib/python3.9/lib-dynload'
[Info  - 2:44:35 PM] (79364)   Looking in python search path '/Users/thejenix/.local_arm64/lib/python/site-packages'
[Info  - 2:44:35 PM] (79364)   Attempting to resolve stub package using root path '/Users/thejenix/.local_arm64/lib/python/site-packages'
[Info  - 2:44:35 PM] (79364)   Attempting to resolve using root path '/Users/thejenix/.local_arm64/lib/python/site-packages'
[Info  - 2:44:35 PM] (79364)   Looking in python search path '/opt/homebrew/lib/python3.9/site-packages'
[Info  - 2:44:35 PM] (79364)   Attempting to resolve stub package using root path '/opt/homebrew/lib/python3.9/site-packages'
[Info  - 2:44:35 PM] (79364)   Attempting to resolve using root path '/opt/homebrew/lib/python3.9/site-packages'
[Info  - 2:44:35 PM] (79364)   Looking in bundled stubs path '/Users/thejenix/.vscode/extensions/ms-python.vscode-pylance-2022.1.4/dist/bundled/stubs'
[Info  - 2:44:35 PM] (79364)   Attempting to resolve stub package using root path '/Users/thejenix/.vscode/extensions/ms-python.vscode-pylance-2022.1.4/dist/bundled/stubs'
[Info  - 2:44:35 PM] (79364)   Attempting to resolve using root path '/Users/thejenix/.vscode/extensions/ms-python.vscode-pylance-2022.1.4/dist/bundled/stubs'
[Info  - 2:44:35 PM] (79364)   Looking for typeshed path
[Info  - 2:44:35 PM] (79364)   Looking for typeshed stubs path
[Info  - 2:44:35 PM] (79364)   Typeshed path not found
(79364) [IDX(2)]     binding: /Users/thejenix/.local_arm64/lib/python/site-packages/lazy_object_proxy/__init__.py (0ms)
(79364) [IDX(2)]     indexing: /Users/thejenix/.local_arm64/lib/python/site-packages/lazy_object_proxy/__init__.py [found 0] (0ms)
(79364) [IDX(2)]     parsing: /opt/homebrew/lib/python3.9/site-packages/pkg_resources/__init__.py [fs read 1ms] (40ms)
(79364) [IDX(2)]     binding: /opt/homebrew/lib/python3.9/site-packages/pkg_resources/__init__.py (2ms)
(79364) [IDX(2)]     indexing: /opt/homebrew/lib/python3.9/site-packages/pkg_resources/__init__.py ...
(79364) [IDX(2)]       parsing: /Users/thejenix/.vscode/extensions/ms-python.vscode-pylance-2022.1.4/dist/typeshed-fallback/stdlib/pkgutil.pyi [fs read 1ms] (3ms)
(79364) [IDX(2)]       binding: /Users/thejenix/.vscode/extensions/ms-python.vscode-pylance-2022.1.4/dist/typeshed-fallback/stdlib/pkgutil.pyi (0ms)
(79364) [IDX(2)]     indexing: /opt/homebrew/lib/python3.9/site-packages/pkg_resources/__init__.py [found 71] (3ms)
(79364) [IDX(2)]   index execution environment /Users/thejenix/Development/src/xxx.io/addins/test_proj [found 8787 in 422 files] (113ms)
(79364) [IDX(2)] index libraries /Users/thejenix/Development/src/xxx.io/addins/test_proj [found 8787 in 1 exec envs] (241ms)
[Info  - 2:44:35 PM] (79364) Indexer done(2). indexed 422 files
[Info  - 2:44:35 PM] (79364) Background analysis(1) root directory: /Users/thejenix/.vscode/extensions/ms-python.vscode-pylance-2022.1.4/dist
[Info  - 2:44:35 PM] (79364) Background analysis(1) started
(79364) Background analysis message: setConfigOptions
(79364) Background analysis message: setImportResolver
(79364) Background analysis message: ensurePartialStubPackages
(79364) Background analysis message: setTrackedFiles
(79364) Background analysis message: markAllFilesDirty
(79364) Background analysis message: setFileOpened
(79364) Background analysis message: analyze
(79364) [BG(1)] analyzing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py ...
(79364) [BG(1)]   parsing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (40275ms)
[Info  - 2:45:15 PM] (79364) [BG(1)] Long operation: parsing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (40275ms)
(79364) [BG(1)]   parsing: /Users/thejenix/.vscode/extensions/ms-python.vscode-pylance-2022.1.4/dist/typeshed-fallback/stdlib/builtins.pyi [fs read 1ms] (39ms)
(79364) [BG(1)]   binding: /Users/thejenix/.vscode/extensions/ms-python.vscode-pylance-2022.1.4/dist/typeshed-fallback/stdlib/builtins.pyi (16ms)
(79364) [BG(1)]   binding: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (1ms)
(79364) [BG(1)]   checking: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py ...
(79364) [BG(1)]     parsing: /Users/thejenix/.vscode/extensions/ms-python.vscode-pylance-2022.1.4/dist/typeshed-fallback/stdlib/typing_extensions.pyi [fs read 1ms] (5ms)
(79364) [BG(1)]     binding: /Users/thejenix/.vscode/extensions/ms-python.vscode-pylance-2022.1.4/dist/typeshed-fallback/stdlib/typing_extensions.pyi (1ms)
(79364) [BG(1)]     parsing: /Users/thejenix/.vscode/extensions/ms-python.vscode-pylance-2022.1.4/dist/typeshed-fallback/stdlib/typing.pyi [fs read 1ms] (8ms)
(79364) [BG(1)]     binding: /Users/thejenix/.vscode/extensions/ms-python.vscode-pylance-2022.1.4/dist/typeshed-fallback/stdlib/typing.pyi (7ms)
(79364) [BG(1)]     parsing: /Users/thejenix/.vscode/extensions/ms-python.vscode-pylance-2022.1.4/dist/typeshed-fallback/stdlib/_typeshed/__init__.pyi [fs read 0ms] (4ms)
(79364) [BG(1)]     binding: /Users/thejenix/.vscode/extensions/ms-python.vscode-pylance-2022.1.4/dist/typeshed-fallback/stdlib/_typeshed/__init__.pyi (1ms)
(79364) [BG(1)]     parsing: /Users/thejenix/.vscode/extensions/ms-python.vscode-pylance-2022.1.4/dist/typeshed-fallback/stdlib/abc.pyi [fs read 0ms] (1ms)
(79364) [BG(1)]     binding: /Users/thejenix/.vscode/extensions/ms-python.vscode-pylance-2022.1.4/dist/typeshed-fallback/stdlib/abc.pyi (0ms)
(79364) [BG(1)]   checking: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (47ms)
(79364) [BG(1)] analyzing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (40378ms)
[Info  - 2:45:15 PM] (79364) [BG(1)] Long operation: analyzing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (40378ms)
(79364) Background analysis message: getDiagnosticsForRange
(79364) Background analysis message: getSemanticTokens full
(79364) [BG(1)] getSemanticTokens full at /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (1ms)
(79364) Background analysis message: getSemanticTokens range
(79364) [BG(1)] getSemanticTokens range 0:0 - 62:0 at /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (1ms)
(79364) Background analysis message: getSemanticTokens range
(79364) [BG(1)] getSemanticTokens range 0:0 - 61:5 at /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (1ms)
(79364) Background analysis message: resumeAnalysis
(79364) [BG(1)] indexing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py [found 1] (0ms)
(79364) Indexing Done: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py
(79364) Background analysis message: getDiagnosticsForRange
(79364) Background analysis message: getDiagnosticsForRange
(79364) Background analysis message: getDiagnosticsForRange
(79364) [FG] parsing: /Users/thejenix/.vscode/extensions/ms-python.vscode-pylance-2022.1.4/dist/typeshed-fallback/stdlib/typing_extensions.pyi [fs read 0ms] (11ms)
(79364) [FG] binding: /Users/thejenix/.vscode/extensions/ms-python.vscode-pylance-2022.1.4/dist/typeshed-fallback/stdlib/typing_extensions.pyi (2ms)
(79364) [FG] parsing: /Users/thejenix/.vscode/extensions/ms-python.vscode-pylance-2022.1.4/dist/typeshed-fallback/stdlib/typing.pyi [fs read 0ms] (27ms)
(79364) [FG] binding: /Users/thejenix/.vscode/extensions/ms-python.vscode-pylance-2022.1.4/dist/typeshed-fallback/stdlib/typing.pyi (5ms)
(79364) [FG] parsing: /Users/thejenix/.vscode/extensions/ms-python.vscode-pylance-2022.1.4/dist/typeshed-fallback/stdlib/_typeshed/__init__.pyi [fs read 0ms] (5ms)
(79364) [FG] binding: /Users/thejenix/.vscode/extensions/ms-python.vscode-pylance-2022.1.4/dist/typeshed-fallback/stdlib/_typeshed/__init__.pyi (0ms)
(79364) [FG] parsing: /Users/thejenix/.vscode/extensions/ms-python.vscode-pylance-2022.1.4/dist/typeshed-fallback/stdlib/abc.pyi [fs read 1ms] (2ms)
(79364) [FG] binding: /Users/thejenix/.vscode/extensions/ms-python.vscode-pylance-2022.1.4/dist/typeshed-fallback/stdlib/abc.pyi (0ms)
(79364) Background analysis message: getDiagnosticsForRange
(79364) Background analysis message: getDiagnosticsForRange
(79364) Background analysis message: getDiagnosticsForRange
(79364) Background analysis message: getDiagnosticsForRange
(79364) Background analysis message: setFileOpened
(79364) Background analysis message: markFilesDirty
(79364) [FG] parsing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (40634ms)
[Info  - 2:46:06 PM] (79364) [FG] Long operation: parsing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (40634ms)
(79364) [FG] binding: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (0ms)
(79364) Background analysis message: analyze
(79364) [FG] parsing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (40973ms)
[Info  - 2:46:47 PM] (79364) [FG] Long operation: parsing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (40973ms)
(79364) [FG] binding: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (0ms)
(79364) [FG] parsing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (41210ms)
[Info  - 2:47:28 PM] (79364) [FG] Long operation: parsing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (41210ms)
(79364) [FG] binding: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (0ms)
(79364) [BG(1)] analyzing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py ...
(79364) [BG(1)]   parsing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (41251ms)
[Info  - 2:47:28 PM] (79364) [BG(1)] Long operation: parsing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (41251ms)
(79364) [BG(1)]   binding: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (0ms)
(79364) [BG(1)]   checking: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (1ms)
(79364) [BG(1)] analyzing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (41252ms)
[Info  - 2:47:28 PM] (79364) [BG(1)] Long operation: analyzing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (41252ms)
(79364) [BG(1)] indexing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (0ms)
(79364) Background analysis message: setFileOpened
(79364) Background analysis message: markFilesDirty
(79364) Background analysis message: getSemanticTokens delta
(79364) [FG] parsing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (41956ms)
[Info  - 2:48:10 PM] (79364) [FG] Long operation: parsing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (41956ms)
(79364) [FG] binding: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (0ms)
(79364) [BG(1)] getSemanticTokens delta previousResultId:1643323515490 at /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py ...
(79364) [BG(1)]   parsing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (41353ms)
[Info  - 2:48:10 PM] (79364) [BG(1)] Long operation: parsing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (41353ms)
(79364) [BG(1)]   binding: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (1ms)
(79364) [BG(1)] getSemanticTokens delta previousResultId:1643323515490 at /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (41361ms)
[Info  - 2:48:10 PM] (79364) [BG(1)] Long operation: getSemanticTokens delta previousResultId:1643323515490 at /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (41361ms)
(79364) Background analysis message: setFileOpened
(79364) Background analysis message: markFilesDirty
(79364) Background analysis message: analyze
(79364) [FG] parsing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (51283ms)
[Info  - 2:49:01 PM] (79364) [FG] Long operation: parsing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (51283ms)
(79364) [FG] binding: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (0ms)
(79364) [BG(1)] analyzing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py ...
(79364) [BG(1)]   parsing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (42195ms)
[Info  - 2:49:01 PM] (79364) [BG(1)] Long operation: parsing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (42195ms)
(79364) [BG(1)]   binding: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (1ms)
(79364) [BG(1)]   checking: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (0ms)
(79364) [BG(1)] analyzing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (42196ms)
[Info  - 2:49:01 PM] (79364) [BG(1)] Long operation: analyzing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (42196ms)
(79364) [BG(1)] indexing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (0ms)
(79364) Background analysis message: getDiagnosticsForRange
(79364) Background analysis message: setFileOpened
(79364) Background analysis message: markFilesDirty
(79364) Background analysis message: analyze
(79364) [BG(1)] analyzing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py ...
(79364) [BG(1)]   parsing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (41918ms)
[Info  - 2:49:01 PM] (79364) [BG(1)] Long operation: parsing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (41918ms)
(79364) [BG(1)]   binding: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (0ms)
(79364) [BG(1)]   checking: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (1ms)
(79364) [BG(1)] analyzing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (41919ms)
[Info  - 2:49:01 PM] (79364) [BG(1)] Long operation: analyzing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (41919ms)
(79364) [BG(1)] indexing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (0ms)
(79364) Background analysis message: getDiagnosticsForRange
(79364) Background analysis message: getDiagnosticsForRange
(79364) Background analysis message: setFileOpened
(79364) Background analysis message: markFilesDirty
(79364) Background analysis message: analyze
(79364) [FG] parsing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (65655ms)
[Info  - 2:50:07 PM] (79364) [FG] Long operation: parsing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (65655ms)
(79364) [FG] binding: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (0ms)
(79364) [BG(1)] analyzing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py ...
(79364) [BG(1)]   parsing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (41795ms)
[Info  - 2:50:07 PM] (79364) [BG(1)] Long operation: parsing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (41795ms)
(79364) [BG(1)]   binding: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (0ms)
(79364) [BG(1)]   checking: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (0ms)
(79364) [BG(1)] analyzing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (41795ms)
[Info  - 2:50:07 PM] (79364) [BG(1)] Long operation: analyzing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (41795ms)
(79364) [BG(1)] indexing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (0ms)
(79364) Background analysis message: setFileOpened
(79364) Background analysis message: markFilesDirty
(79364) Background analysis message: analyze
(79364) [FG] completion at /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py:19:74 (4ms)
(79364) [FG] parsing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (52583ms)
[Info  - 2:51:00 PM] (79364) [FG] Long operation: parsing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (52583ms)
(79364) [FG] binding: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (1ms)
(79364) [BG(1)] analyzing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py ...
(79364) [BG(1)]   parsing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (51784ms)
[Info  - 2:51:00 PM] (79364) [BG(1)] Long operation: parsing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (51784ms)
(79364) [BG(1)]   binding: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (0ms)
(79364) [BG(1)]   checking: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (0ms)
(79364) [BG(1)] analyzing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (51784ms)
[Info  - 2:51:00 PM] (79364) [BG(1)] Long operation: analyzing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (51784ms)
(79364) [BG(1)] indexing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (0ms)
(79364) Background analysis message: getDiagnosticsForRange
(79364) Background analysis message: getDiagnosticsForRange
(79364) Background analysis message: getDiagnosticsForRange
(79364) Background analysis message: getDiagnosticsForRange
(79364) Background analysis message: setFileOpened
(79364) Background analysis message: markFilesDirty
(79364) Background analysis message: analyze
(79364) [FG] parsing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (98222ms)
[Info  - 2:52:38 PM] (79364) [FG] Long operation: parsing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (98222ms)
(79364) [FG] binding: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (0ms)
(79364) [BG(1)] analyzing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py ...
(79364) [BG(1)]   parsing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (65748ms)
[Info  - 2:52:38 PM] (79364) [BG(1)] Long operation: parsing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (65748ms)
(79364) [BG(1)]   binding: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (1ms)
(79364) [BG(1)]   checking: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (0ms)
(79364) [BG(1)] analyzing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (65749ms)
[Info  - 2:52:38 PM] (79364) [BG(1)] Long operation: analyzing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (65749ms)
(79364) [BG(1)] indexing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (0ms)
(79364) Background analysis message: getDiagnosticsForRange
(79364) Background analysis message: setFileOpened
(79364) Background analysis message: markFilesDirty
(79364) Background analysis message: analyze
(79364) [BG(1)] analyzing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py ...
(79364) [BG(1)]   parsing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (51711ms)
[Info  - 2:52:38 PM] (79364) [BG(1)] Long operation: parsing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (51711ms)
(79364) [BG(1)]   binding: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (0ms)
(79364) [BG(1)]   checking: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (0ms)
(79364) [BG(1)] analyzing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (51711ms)
[Info  - 2:52:38 PM] (79364) [BG(1)] Long operation: analyzing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (51711ms)
(79364) [BG(1)] indexing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (0ms)
(79364) Background analysis message: getDiagnosticsForRange
(79364) Background analysis message: getDiagnosticsForRange
(79364) Background analysis message: setFileOpened
(79364) Background analysis message: markFilesDirty
(79364) Background analysis message: analyze
(79364) [FG] parsing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (93162ms)
[Info  - 2:57:15 PM] (79364) [FG] Long operation: parsing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (93162ms)
(79364) [FG] binding: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (1ms)
(79364) [BG(1)] analyzing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py ...
(79364) [BG(1)]   parsing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (93067ms)
[Info  - 2:57:15 PM] (79364) [BG(1)] Long operation: parsing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (93067ms)
(79364) [BG(1)]   binding: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (1ms)
(79364) [BG(1)]   checking: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (0ms)
(79364) [BG(1)] analyzing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (93068ms)
[Info  - 2:57:15 PM] (79364) [BG(1)] Long operation: analyzing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (93068ms)
(79364) [BG(1)] indexing: /Users/thejenix/Development/src/xxx.io/addins/test_proj/test.py (0ms)

Code Snippet / Additional information

This is the statement, formatted using Black for readability. My project consists of an empty folder with test.py that contains this code. When I open this folder in VSCode, I see the above actual behavior.

def foo():
    func(
        (
            (
                (
                    (
                        (
                            (
                                (
                                    (
                                        (
                                            (
                                                (
                                                    (
                                                        (
                                                            (
                                                                (
                                                                    "text "
                                                                    + func2(
                                                                        (
                                                                            "null"
                                                                            if a is None
                                                                            else a
                                                                        )
                                                                        + (
                                                                            "null"
                                                                            if b is None
                                                                            else b
                                                                        )
                                                                    )
                                                                )
                                                                + " "
                                                            )
                                                            + (
                                                                "null"
                                                                if x is None
                                                                else x
                                                            )
                                                        )
                                                        + " "
                                                    )
                                                    + ("null" if y is None else y)
                                                )
                                                + " "
                                            )
                                            + func2(
                                                (("null" if ((y is None)) else str(y)))
                                            )
                                        )
                                        + " "
                                    )
                                    + ("null" if y is None else y)
                                )
                                + " => "
                            )
                            + str(z1)
                        )
                        + " "
                    )
                    + str(z2)
                )
                + " "
            )
            + str(type(z1))
        )
    )
@theJenix
Copy link
Author

I didn't know if this belonged in the bug report or a comment, so I figured comment: the actual statement in my production code (which I anonymized in the above code) hasn't changed in many months, and I'm pretty sure this worked in a previous version of Pylance. Currently going back thru older versions to confirm this.

@theJenix
Copy link
Author

Can confirm: Version 2021.12.22 works as expected. Starting in version 2022.1.0, this file takes a long time to parse and analyze.

@erictraut
Copy link
Contributor

Thanks for the bug report. I'm able to repro the problem, and I understand the cause. It has to do with a new syntactic construct that is being added to Python 3.11 for callable types. The new syntax creates a situation in the parser that requires an arbitrary amount of lookahead. The current implementation is O(n^m) where "m" is the number of nested parentheses. In your sample, "m" is very large. I'll need to see if I can come up with a different approach in the parser.

In the meantime, you can avoid this problem by breaking up your code into something that is not so deeply nested.

@erictraut
Copy link
Contributor

I found a solution that mitigates the performance overhead in the parser. This change may not make it into this week's release of pylance, in which case it will be in next week's release.

@erictraut erictraut added bug Something isn't working fixed in next version (main) A fix has been implemented and will appear in an upcoming version and removed triage labels Jan 28, 2022
@theJenix
Copy link
Author

Thanks Eric! The code is actually generated and I don't control the generator; I've reverted back to 2021.12.2 for the time being and will take a look at next week's version when it is ready.

@debonte
Copy link
Contributor

debonte commented Feb 4, 2022

This issue has been fixed in version 2022.2.0, which we've just released. You can find the changelog here: CHANGELOG.md

@debonte debonte closed this as completed Feb 4, 2022
@davrot
Copy link

davrot commented Feb 17, 2022

This issue has been fixed in version 2022.2.0, which we've just released. You can find the changelog here: CHANGELOG.md

Sorry, but I got a similar problem over the last weekend too... If I click on the appended py file under vs code, Pylance (2022.2.1) goes on a 100% CPU vacation and never comes back. I have to change the py file and restart the language server. All other py files work fine. But this file (and modified version of it) break Pylance.

Version: 1.64.2
Commit: f80445acd5a3dadef24aa209168452a3d97cc326
Datum: 2022-02-09T22:02:29.527Z
Electron: 13.5.2
Chromium: 91.0.4472.164
Node.js: 14.16.0
V8: 9.1.269.39-electron.0
Betriebssystem: Linux x64 5.15.16-200.fc35.x86_64
log_pylance_2022.2.1.txt
learn_it_last_layer_mnist_local_many.py.txt

@debonte
Copy link
Contributor

debonte commented Feb 17, 2022

@davrot, we had a recent perf regression which caused the same symptom. Can you see if your issue is fixed in today's release of Pylance -- 2022.2.3?

@davrot
Copy link

davrot commented Feb 17, 2022

Just tested it with 2022.2.3 (see the log). Same problem. Sorry!

log_pylance_2022.2.3.txt

@erictraut
Copy link
Contributor

@davrot, I'm able to repro the problem you're seeing. I've created a separate tracking bug in the pyright repo: microsoft/pyright#3082.

@davrot
Copy link

davrot commented Feb 19, 2022

@davrot, I'm able to repro the problem you're seeing. I've created a separate tracking bug in the pyright repo: microsoft/pyright#3082.

Thank you!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working fixed in next version (main) A fix has been implemented and will appear in an upcoming version
Projects
None yet
Development

No branches or pull requests

4 participants