pylance-release icon indicating copy to clipboard operation
pylance-release copied to clipboard

Published 20 hours ago • verified publisher icon microsoft

Syntax highlighting and analysis concerningly slow with multiple tuple returning function calls

Open AyushPJ opened this issue 2 years ago • 1 comments

Environment data

  • Language Server version: 2022.6.10
  • OS and version: Ubuntu 20.04.4 LTS (Kernel: 5.13.0-44-generic)
  • Python version: Python 3.8.10

Code Snippet

def foo (yy, zz):
    yy = zz['cc']
    return (yy, dict(zz=zz['cc']))

def bar(aa, bb):

    count = 0
    while count < 10:
        
        count += 1
        aa, bb = foo(aa,dict(cc=bb))
        
        aa, bb = foo(aa,dict(cc=bb))



        aa, bb = foo(aa,dict(cc=bb))

        aa, bb = foo(aa,dict(cc=bb))

        if aa:
            aa, bb = foo(aa,dict(cc=bb))

        aa, bb = foo(aa,dict(cc=bb))

        aa, bb = foo(aa,dict(cc=bb))

        aa, bb = foo(aa,dict(cc=bb))

        aa, bb = foo(aa,dict(cc=bb))

        aa, bb = foo(aa,dict(cc=bb))
        

def main():
    bar(1, 2)
   

main()

Repro Steps

  1. Open the file in VS Code with Python and Pylance extensions installed.

Expected behavior

Syntax highlighting in few seconds with little performance hit.

Actual behavior

Syntax highlighting and analysis takes minutes (sometimes it never finishes). Shows 100% CPU usage on one of the logical cores in system monitor.

Output from top -p $(pgrep -d ',' code) Peek 2022-06-09 11-19

Logs

[Info  - 11:00:21 AM] (57684) Pylance language server 2022.6.10 (pyright bbc42826) starting
[Info  - 11:00:21 AM] (57684) Server root directory: /home/ayushpj/.vscode/extensions/ms-python.vscode-pylance-2022.6.10/dist
Notebook support: Legacy
[Info  - 11:00:21 AM] (57684) No pyproject.toml file found.
[Info  - 11:00:21 AM] (57684) Setting pythonPath for service "<default>": "/bin/python3"
[Warn  - 11:00:21 AM] (57684) stubPath typings is not a valid directory.
[Info  - 11:00:21 AM] (57684) Assuming Python version 3.8
[Info  - 11:00:21 AM] (57684) Assuming Python platform Linux
[Info  - 11:00:22 AM] (57684) Search paths for <default>
[Info  - 11:00:22 AM] (57684)   /home/ayushpj/.vscode/extensions/ms-python.vscode-pylance-2022.6.10/dist/typeshed-fallback/stdlib
[Info  - 11:00:22 AM] (57684)   typings
[Info  - 11:00:22 AM] (57684)   /home/ayushpj/.vscode/extensions/ms-python.vscode-pylance-2022.6.10/dist/typeshed-fallback/stubs/...
[Info  - 11:00:22 AM] (57684)   /home/ayushpj/.vscode/extensions/ms-python.vscode-pylance-2022.6.10/dist/bundled/stubs
[Info  - 11:00:22 AM] (57684)   /usr/lib/python3.8
[Info  - 11:00:22 AM] (57684)   /usr/lib/python3.8/lib-dynload
[Info  - 11:00:22 AM] (57684)   /home/ayushpj/.local/lib/python3.8/site-packages
[Info  - 11:00:22 AM] (57684)   /usr/local/lib/python3.8/dist-packages
[Info  - 11:00:22 AM] (57684)   /usr/lib/python3/dist-packages
[Info  - 11:00:22 AM] (57684) Adding fs watcher for library directories:
 /usr/lib/python3.8
/usr/lib/python3.8/lib-dynload
/home/ayushpj/.local/lib/python3.8/site-packages
/usr/local/lib/python3.8/dist-packages
/usr/lib/python3/dist-packages
[Info  - 11:00:22 AM] (57684) Searching for source files
[Info  - 11:00:22 AM] (57684) No source files found.
(57684) [IDX(FG)] index libraries  (index) ...
(57684) [IDX(FG)]   read stdlib indices (32ms)
(57684) [IDX(FG)] index libraries  (index) [succeed] (33ms)
[Info  - 11:00:22 AM] (57684) No pyproject.toml file found.
[Info  - 11:00:22 AM] (57684) Setting pythonPath for service "<default>": "/bin/python3"
[Warn  - 11:00:22 AM] (57684) stubPath typings is not a valid directory.
[Info  - 11:00:22 AM] (57684) Assuming Python version 3.8
[Info  - 11:00:22 AM] (57684) Assuming Python platform Linux
[Info  - 11:00:22 AM] (57684) Search paths for <default>
[Info  - 11:00:22 AM] (57684)   /home/ayushpj/.vscode/extensions/ms-python.vscode-pylance-2022.6.10/dist/typeshed-fallback/stdlib
[Info  - 11:00:22 AM] (57684)   typings
[Info  - 11:00:22 AM] (57684)   /home/ayushpj/.vscode/extensions/ms-python.vscode-pylance-2022.6.10/dist/typeshed-fallback/stubs/...
[Info  - 11:00:22 AM] (57684)   /home/ayushpj/.vscode/extensions/ms-python.vscode-pylance-2022.6.10/dist/bundled/stubs
[Info  - 11:00:22 AM] (57684)   /usr/lib/python3.8
[Info  - 11:00:22 AM] (57684)   /usr/lib/python3.8/lib-dynload
[Info  - 11:00:22 AM] (57684)   /home/ayushpj/.local/lib/python3.8/site-packages
[Info  - 11:00:22 AM] (57684)   /usr/local/lib/python3.8/dist-packages
[Info  - 11:00:22 AM] (57684)   /usr/lib/python3/dist-packages
[Info  - 11:00:22 AM] (57684) Adding fs watcher for library directories:
 /usr/lib/python3.8
/usr/lib/python3.8/lib-dynload
/home/ayushpj/.local/lib/python3.8/site-packages
/usr/local/lib/python3.8/dist-packages
/usr/lib/python3/dist-packages
[Info  - 11:00:22 AM] (57684) Searching for source files
[Info  - 11:00:22 AM] (57684) No source files found.
(57684) [IDX(FG)] index libraries  (index) ...
(57684) [IDX(FG)]   read stdlib indices (27ms)
(57684) [IDX(FG)] index libraries  (index) [succeed] (27ms)
(57684) [FG] parsing: /home/ayushpj/Projects/Pylance-Issue/pylance_issue.py (33ms)
(57684) [FG] parsing: /home/ayushpj/.vscode/extensions/ms-python.vscode-pylance-2022.6.10/dist/typeshed-fallback/stdlib/builtins.pyi [fs read 3ms] (119ms)
(57684) [FG] binding: /home/ayushpj/.vscode/extensions/ms-python.vscode-pylance-2022.6.10/dist/typeshed-fallback/stdlib/builtins.pyi (40ms)
(57684) [FG] binding: /home/ayushpj/Projects/Pylance-Issue/pylance_issue.py (3ms)
[Info  - 11:00:22 AM] (57684) Background analysis(1) root directory: /home/ayushpj/.vscode/extensions/ms-python.vscode-pylance-2022.6.10/dist
[Info  - 11:00:22 AM] (57684) Background analysis(1) started
(57684) Background analysis message: setConfigOptions
(57684) Background analysis message: setImportResolver
(57684) Background analysis message: ensurePartialStubPackages
(57684) Background analysis message: setTrackedFiles
(57684) Background analysis message: markAllFilesDirty
(57684) Background analysis message: setFileOpened
(57684) Background analysis message: setConfigOptions
(57684) Background analysis message: setImportResolver
(57684) Background analysis message: ensurePartialStubPackages
(57684) Background analysis message: setTrackedFiles
(57684) Background analysis message: markAllFilesDirty
(57684) Background analysis message: analyze
(57684) [BG(1)] analyzing: /home/ayushpj/Projects/Pylance-Issue/pylance_issue.py ...
(57684) [BG(1)]   parsing: /home/ayushpj/Projects/Pylance-Issue/pylance_issue.py (21ms)
(57684) [BG(1)]   parsing: /home/ayushpj/.vscode/extensions/ms-python.vscode-pylance-2022.6.10/dist/typeshed-fallback/stdlib/builtins.pyi [fs read 2ms] (78ms)
(57684) [BG(1)]   binding: /home/ayushpj/.vscode/extensions/ms-python.vscode-pylance-2022.6.10/dist/typeshed-fallback/stdlib/builtins.pyi (28ms)
(57684) [BG(1)]   binding: /home/ayushpj/Projects/Pylance-Issue/pylance_issue.py (2ms)
(57684) [BG(1)]   checking: /home/ayushpj/Projects/Pylance-Issue/pylance_issue.py ...
(57684) [BG(1)]     parsing: /home/ayushpj/.vscode/extensions/ms-python.vscode-pylance-2022.6.10/dist/typeshed-fallback/stdlib/typing_extensions.pyi [fs read 1ms] (6ms)
(57684) [BG(1)]     binding: /home/ayushpj/.vscode/extensions/ms-python.vscode-pylance-2022.6.10/dist/typeshed-fallback/stdlib/typing_extensions.pyi (2ms)
(57684) [BG(1)]     parsing: /home/ayushpj/.vscode/extensions/ms-python.vscode-pylance-2022.6.10/dist/typeshed-fallback/stdlib/typing.pyi [fs read 0ms] (23ms)
(57684) [BG(1)]     binding: /home/ayushpj/.vscode/extensions/ms-python.vscode-pylance-2022.6.10/dist/typeshed-fallback/stdlib/typing.pyi (5ms)
(57684) [BG(1)]     parsing: /home/ayushpj/.vscode/extensions/ms-python.vscode-pylance-2022.6.10/dist/typeshed-fallback/stdlib/_typeshed/__init__.pyi [fs read 0ms] (14ms)
(57684) [BG(1)]     binding: /home/ayushpj/.vscode/extensions/ms-python.vscode-pylance-2022.6.10/dist/typeshed-fallback/stdlib/_typeshed/__init__.pyi (1ms)
(57684) [BG(1)]     parsing: /home/ayushpj/.vscode/extensions/ms-python.vscode-pylance-2022.6.10/dist/typeshed-fallback/stdlib/abc.pyi [fs read 0ms] (0ms)
(57684) [BG(1)]     binding: /home/ayushpj/.vscode/extensions/ms-python.vscode-pylance-2022.6.10/dist/typeshed-fallback/stdlib/abc.pyi (1ms)
(57684) [BG(1)]     parsing: /home/ayushpj/.vscode/extensions/ms-python.vscode-pylance-2022.6.10/dist/typeshed-fallback/stdlib/collections/abc.pyi [fs read 0ms] (0ms)
(57684) [BG(1)]     binding: /home/ayushpj/.vscode/extensions/ms-python.vscode-pylance-2022.6.10/dist/typeshed-fallback/stdlib/collections/abc.pyi ...
(57684) [BG(1)]       parsing: /home/ayushpj/.vscode/extensions/ms-python.vscode-pylance-2022.6.10/dist/typeshed-fallback/stdlib/_collections_abc.pyi [fs read 0ms] (0ms)
(57684) [BG(1)]       binding: /home/ayushpj/.vscode/extensions/ms-python.vscode-pylance-2022.6.10/dist/typeshed-fallback/stdlib/_collections_abc.pyi (1ms)
(57684) [BG(1)]     binding: /home/ayushpj/.vscode/extensions/ms-python.vscode-pylance-2022.6.10/dist/typeshed-fallback/stdlib/collections/abc.pyi (1ms)
(57684) [FG] parsing: /home/ayushpj/.vscode/extensions/ms-python.vscode-pylance-2022.6.10/dist/typeshed-fallback/stdlib/typing_extensions.pyi [fs read 2ms] (12ms)
(57684) [FG] binding: /home/ayushpj/.vscode/extensions/ms-python.vscode-pylance-2022.6.10/dist/typeshed-fallback/stdlib/typing_extensions.pyi (3ms)
(57684) [FG] parsing: /home/ayushpj/.vscode/extensions/ms-python.vscode-pylance-2022.6.10/dist/typeshed-fallback/stdlib/typing.pyi [fs read 0ms] (34ms)
(57684) [FG] binding: /home/ayushpj/.vscode/extensions/ms-python.vscode-pylance-2022.6.10/dist/typeshed-fallback/stdlib/typing.pyi (11ms)
(57684) [FG] parsing: /home/ayushpj/.vscode/extensions/ms-python.vscode-pylance-2022.6.10/dist/typeshed-fallback/stdlib/_typeshed/__init__.pyi [fs read 0ms] (21ms)
(57684) [FG] binding: /home/ayushpj/.vscode/extensions/ms-python.vscode-pylance-2022.6.10/dist/typeshed-fallback/stdlib/_typeshed/__init__.pyi (2ms)
(57684) [FG] parsing: /home/ayushpj/.vscode/extensions/ms-python.vscode-pylance-2022.6.10/dist/typeshed-fallback/stdlib/abc.pyi [fs read 0ms] (2ms)
(57684) [FG] binding: /home/ayushpj/.vscode/extensions/ms-python.vscode-pylance-2022.6.10/dist/typeshed-fallback/stdlib/abc.pyi (0ms)
(57684) [FG] parsing: /home/ayushpj/.vscode/extensions/ms-python.vscode-pylance-2022.6.10/dist/typeshed-fallback/stdlib/collections/abc.pyi [fs read 0ms] (0ms)
(57684) [FG] binding: /home/ayushpj/.vscode/extensions/ms-python.vscode-pylance-2022.6.10/dist/typeshed-fallback/stdlib/collections/abc.pyi ...
(57684) [FG]   parsing: /home/ayushpj/.vscode/extensions/ms-python.vscode-pylance-2022.6.10/dist/typeshed-fallback/stdlib/_collections_abc.pyi [fs read 0ms] (1ms)
(57684) [FG]   binding: /home/ayushpj/.vscode/extensions/ms-python.vscode-pylance-2022.6.10/dist/typeshed-fallback/stdlib/_collections_abc.pyi (1ms)
(57684) [FG] binding: /home/ayushpj/.vscode/extensions/ms-python.vscode-pylance-2022.6.10/dist/typeshed-fallback/stdlib/collections/abc.pyi (3ms)
(57684) [FG] parsing: /tmp/pyright-57684-7NaNwW2BiNvG/builtins-57684-1oFgcd2Pt7hN-.py [fs read 1ms] (80ms)
(57684) [FG] binding: /tmp/pyright-57684-7NaNwW2BiNvG/builtins-57684-1oFgcd2Pt7hN-.py (37ms)

Misc.

It's my first time noticing this. I see no issues when I don't use multiple tuple returning function calls in this fashion and I tested it in some of my other projects which leads me to believe it's the primary cause of it.

Thanks in advance!

AyushPJ avatar Jun 09 '22 06:06 AyushPJ

Thanks for reporting this. Yes, you're hitting a case that is difficult for the type analyzer to handle. I'll take a look at ways to mitigate the performance issue.

Since this is pyright, the type checker upon which pylance is built, I've created a tracking bug in the pyright project.

erictraut avatar Jun 09 '22 07:06 erictraut

I've done a series of performance improvements, and I've dropped the analysis time from 10's of seconds to about 2 seconds on my machine. This is definitely a challenging code sample for a static type evaluator to handle, and I'm reaching diminishing returns with optimizations.

I'll note that if I add type annotations to the two input parameters aa and bb in the bar function, the analysis time drops to tens of milliseconds. Without these type annotations, the type analyzer needs to do a lot of work to infer the types of these symbols.

I'm going to mark this as resolved at this point because I don't think there's much more I can do to improve the perf.

erictraut avatar Sep 04 '22 21:09 erictraut

I've marked it as "fixed in next version", but the optimizations are already in place, so I think it's fine to close this issue.

erictraut avatar Sep 04 '22 21:09 erictraut

Thanks for your efforts! I understand it is a very hard case for the type analyzer as it tries to resolve the dynamic return type of foo which is difficult to know ahead of time. Nevertheless, really appreciate you bringing down the time to 2 seconds; I tested it and it is a big improvement. Type annotations seem to improve it even further but then the type of the variable doesn't update, which I guess is fair and meant to be. I shall close this issue now.

AyushPJ avatar Sep 06 '22 05:09 AyushPJ