Unbearably slow in my code base: https://github.com/scverse/scanpy #5474

rchiodo · 2023-07-06T16:05:04Z

          Still unbearably slow in my code base: https://github.com/scverse/scanpy

Saving files takes multiple seconds. VS Code waits and eventually shows a popup “Getting code actions from ''Python"”.

When setting "python.languageServer": "None", saving works as expected.

Why will VS Code wait for Pylance to save things? I have only source.fixAll.ruff activated, so the Python extension shouldn’t be consulted when saving a file at all.

{
    "[python]": {
        "editor.formatOnSave": true,
        "editor.defaultFormatter": "ms-python.black-formatter",
        "editor.codeActionsOnSave": {
            "source.fixAll.ruff": true,
        },
    },
    "python.testing.pytestArgs": ["scanpy/tests"],
    "python.testing.unittestEnabled": false,
    "python.testing.pytestEnabled": true,
    "python.languageServer": "Pylance",
}

Originally posted by @flying-sheep in microsoft/pylance-release#4263 (comment)

The text was updated successfully, but these errors were encountered:

rchiodo · 2023-07-06T20:15:53Z

@flying-sheep can you upload a log as described here?

https://github.com/microsoft/pylance-release/blob/main/TROUBLESHOOTING.md#filing-an-issue

I cannot reproduce any slowdown with that configuration in that same project. A log may at least point to what part is taking so long.

Does it only reproduce for certain files? I've tried a bunch and they all save instantly.

flying-sheep · 2023-07-07T07:14:07Z

Those are the log entries generated when typing a single space (not at the end of a line) and saving the file scanpy/tests/test_neighbors.py

The log entries however only appear after the majority of waiting is over:

hit save
wait 2-3 seconds
the popup appears (not always)
the log entries come for ~1sec
the popup disappears, the black formatter is run

Disabling Pylance makes the wait go away. The black formatter runs in <1sec and is not responsible for the wait time.

2023-07-07 09:23:38.795 [info] (12508) Background analysis message: setFileOpened
2023-07-07 09:23:38.834 [info] (12508) Background analysis message: markFilesDirty
2023-07-07 09:23:38.836 [info] (12508) [FG] parsing: /home/phil/Dev/Python/Single Cell/scanpy/scanpy/tests/test_neighbors.py (3ms)
2023-07-07 09:23:38.843 [info] (12508) [FG] binding: /home/phil/Dev/Python/Single Cell/scanpy/scanpy/tests/test_neighbors.py (1ms)
2023-07-07 09:23:38.844 [info] (12508) Background analysis message: getDiagnosticsForRange
2023-07-07 09:23:38.845 [info] (12508) Background analysis message: getDiagnosticsForRange
2023-07-07 09:23:38.845 [info] (12508) Background analysis message: getSemanticTokens delta
2023-07-07 09:23:39.033 [info] (12508) [BG(1)] getSemanticTokens delta previousResultId:1688714579502 at /home/phil/Dev/Python/Single Cell/scanpy/scanpy/tests/test_neighbors.py ...
2023-07-07 09:23:39.034 [info] (12508) [BG(1)]   parsing: /home/phil/Dev/Python/Single Cell/scanpy/scanpy/tests/test_neighbors.py (8ms)
2023-07-07 09:23:39.034 [info] (12508) [BG(1)]   binding: /home/phil/Dev/Python/Single Cell/scanpy/scanpy/tests/test_neighbors.py (1ms)
2023-07-07 09:23:39.034 [info] [Info  - 09:23:39] (12508) SourceFile: Received fs event 'add' for path '/home/phil/Dev/Python/Single Cell/scanpy/.git/index'
2023-07-07 09:23:39.590 [info] (12508) [BG(1)] getSemanticTokens delta previousResultId:1688714579502 at /home/phil/Dev/Python/Single Cell/scanpy/scanpy/tests/test_neighbors.py (793ms)
2023-07-07 09:23:39.591 [info] (12508) Background analysis message: getDiagnosticsForRange
2023-07-07 09:23:39.591 [info] (12508) Background analysis message: analyze
2023-07-07 09:23:39.611 [info] (12508) [BG(1)] analyzing: /home/phil/Dev/Python/Single Cell/scanpy/scanpy/tests/test_neighbors.py ...
2023-07-07 09:23:39.611 [info] (12508) [BG(1)]   checking: /home/phil/Dev/Python/Single Cell/scanpy/scanpy/tests/test_neighbors.py (21ms)
2023-07-07 09:23:39.611 [info] (12508) [BG(1)] analyzing: /home/phil/Dev/Python/Single Cell/scanpy/scanpy/tests/test_neighbors.py (21ms)
2023-07-07 09:23:39.612 [info] (12508) Background analysis message: resumeAnalysis
2023-07-07 09:23:39.612 [info] (12508) [BG(1)] indexing: /home/phil/Dev/Python/Single Cell/scanpy/scanpy/tests/test_neighbors.py [found 23] (0ms)
2023-07-07 09:23:39.613 [info] (12508) Indexing Done: /home/phil/Dev/Python/Single Cell/scanpy/scanpy/tests/test_neighbors.py
2023-07-07 09:23:39.842 [info] (12508) Background analysis message: setFileOpened
2023-07-07 09:23:39.842 [info] (12508) Background analysis message: markFilesDirty
2023-07-07 09:23:40.092 [info] (12508) Background analysis message: analyze
2023-07-07 09:23:40.108 [info] (12508) [BG(1)] analyzing: /home/phil/Dev/Python/Single Cell/scanpy/scanpy/tests/test_neighbors.py ...
2023-07-07 09:23:40.109 [info] (12508) [BG(1)]   parsing: /home/phil/Dev/Python/Single Cell/scanpy/scanpy/tests/test_neighbors.py (5ms)
2023-07-07 09:23:40.109 [info] (12508) [BG(1)]   binding: /home/phil/Dev/Python/Single Cell/scanpy/scanpy/tests/test_neighbors.py (1ms)
2023-07-07 09:23:40.165 [info] (12508) [FG] parsing: /home/phil/Dev/Python/Single Cell/scanpy/scanpy/tests/test_neighbors.py (2ms)
2023-07-07 09:23:40.167 [info] (12508) [FG] binding: /home/phil/Dev/Python/Single Cell/scanpy/scanpy/tests/test_neighbors.py (1ms)
2023-07-07 09:23:40.258 [info] [Info  - 09:23:40] (12508) SourceFile: Received fs event 'change' for path '/home/phil/Dev/Python/Single Cell/scanpy/scanpy/tests/test_neighbors.py'
2023-07-07 09:23:40.275 [info] (12508) [BG(1)]   checking: /home/phil/Dev/Python/Single Cell/scanpy/scanpy/tests/test_neighbors.py (171ms)
2023-07-07 09:23:40.276 [info] (12508) [BG(1)] analyzing: /home/phil/Dev/Python/Single Cell/scanpy/scanpy/tests/test_neighbors.py (177ms)
2023-07-07 09:23:40.276 [info] (12508) [BG(1)] indexing: /home/phil/Dev/Python/Single Cell/scanpy/scanpy/tests/test_neighbors.py [found 23] (1ms)
2023-07-07 09:23:40.276 [info] (12508) Indexing Done: /home/phil/Dev/Python/Single Cell/scanpy/scanpy/tests/test_neighbors.py
2023-07-07 09:23:40.276 [info] (12508) Background analysis message: getDiagnosticsForRange
2023-07-07 09:23:40.276 [info] (12508) Background analysis message: markFilesDirty
2023-07-07 09:23:40.276 [info] (12508) Background analysis message: getDiagnosticsForRange
2023-07-07 09:23:40.415 [info] (12508) Background analysis message: analyze
2023-07-07 09:23:40.878 [info] (12508) [BG(1)] analyzing: /home/phil/Dev/Python/Single Cell/scanpy/scanpy/tests/test_neighbors.py ...
2023-07-07 09:23:40.878 [info] (12508) [BG(1)]   checking: /home/phil/Dev/Python/Single Cell/scanpy/scanpy/tests/test_neighbors.py (463ms)
2023-07-07 09:23:40.878 [info] (12508) [BG(1)] analyzing: /home/phil/Dev/Python/Single Cell/scanpy/scanpy/tests/test_neighbors.py (463ms)
2023-07-07 09:23:40.879 [info] (12508) Background analysis message: getSemanticTokens delta
2023-07-07 09:23:40.884 [info] (12508) [BG(1)] getSemanticTokens delta previousResultId:1688714618806 at /home/phil/Dev/Python/Single Cell/scanpy/scanpy/tests/test_neighbors.py (6ms)
2023-07-07 09:23:40.885 [info] (12508) Background analysis message: resumeAnalysis
2023-07-07 09:23:40.885 [info] (12508) [BG(1)] indexing: /home/phil/Dev/Python/Single Cell/scanpy/scanpy/tests/test_neighbors.py [found 23] (0ms)
2023-07-07 09:23:40.885 [info] (12508) Indexing Done: /home/phil/Dev/Python/Single Cell/scanpy/scanpy/tests/test_neighbors.py
2023-07-07 09:23:40.913 [info] [Info  - 09:23:40] (12508) SourceFile: Received fs event 'add' for path '/home/phil/Dev/Python/Single Cell/scanpy/.git/index'

Jacques-Peeters · 2023-07-07T08:56:47Z

To help other stuck in the same situation, switching back to 2023.6.40 version solves the issue.

rchiodo · 2023-07-07T16:35:50Z

Not sure how 2023.6.40 solves the problem, we haven't really changed much of anything in the last week.

However, I am able to cause analysis to take a long time if I try to save test_neighbors.py.

This setting is causing VS code to wait for all code action providers (not sure why VS code does this though):

    "[python]": {
        "editor.formatOnSave": true,
}

So, the combination of that setting and the fact that test_neighbors takes a very long time to analyze is the reason for the slow down.

I'm guessing the work on this issue here is why format on save forces code actions to be gathered:
microsoft/vscode#67147

rchiodo · 2023-07-07T16:41:25Z

Here's the directions for my repro:

Git clone the https://github.com/scverse/scanpy
pip-compile -o requirements.txt pyproject.toml
python -m venv .venv
activate .venv
pip install -r requirements.txt
pip install pytest
change settings as shown above
open scanpy\tests\test_neighbors.py
Try saving the file

I get output like so:

2023-07-07 09:41:08.511 [info] [Info  - 9:41:08 AM] (19388) [BG(1)] Long operation: checking: c:\Users\rchiodo\source\testing\scanpy\scanpy\tests\test_neighbors.py (4166ms)
2023-07-07 09:41:08.511 [info] [Info  - 9:41:08 AM] (19388) Heap stats: total_heap_size=160MB, used_heap_size=121MB, total_physical_size=160MB, total_available_size=1921MB, heap_size_limit=2072MB

rchiodo · 2023-07-07T16:57:18Z

And I cannot repro it on 2023.6.40 either.

rchiodo · 2023-07-07T17:09:36Z

The difference between the two versions seems to be something marking the file as continually dirty:

2023-07-07 10:05:05.786 [info] (12332) Background analysis message: getDiagnosticsForRange
2023-07-07 10:05:05.787 [info] (12332) Background analysis message: setFileOpened
2023-07-07 10:05:05.787 [info] (12332) Background analysis message: markFilesDirty
2023-07-07 10:05:05.794 [info] (12332) Background analysis message: setFileOpened
2023-07-07 10:05:05.794 [info] (12332) Background analysis message: markFilesDirty
2023-07-07 10:05:05.795 [info] (12332) Background analysis message: setFileOpened
2023-07-07 10:05:05.795 [info] (12332) Background analysis message: markFilesDirty
2023-07-07 10:05:05.795 [info] (12332) Background analysis message: analyze

Not sure which file is being marked dirty, but these messages all appear after saving a single file. The same doesn't occur in 2023.6.40.

rchiodo · 2023-07-10T20:48:10Z

This change is the cause of the slowdown:
https://github.com/microsoft/pyrx/commit/6d83e146e412424e83168940f9046b0745bdf94d

Not sure why yet. That change seems correct to me.

rchiodo · 2023-07-10T20:50:11Z

With that change, analyzing the test_neighbors.py takes 5000ms. Without it takes 500ms.

Jacques-Peeters · 2023-07-11T09:35:02Z

This change is the cause of the slowdown: https://github.com/microsoft/pyrx/commit/6d83e146e412424e83168940f9046b0745bdf94d

Not sure why yet. That change seems correct to me.

We don't have access to this private repo. So can't say much, and hope my comment won't look like as me being an asshole.

What I know is this isn't the first time of similar problem happening (few months ago it did) and users like me lost hours/days of work due to this, saying to our managers/PM VSCode is not working I can't work this week is very frustrating experience.
And understanding that we have to downgrade pylance isn't obvious.

If the problem is due to the same code being change again, but me worth finding a way to avoid this in the future as this is extremely painful.

flying-sheep · 2023-07-11T09:56:04Z

I want to express that I value all the hard work going into this project. Python was in desperate need for a good language server that integrates with typing.

@Jacques-Peeters I assume there is performance testing, and I assume pathological cases like this will be tested in the future. We’re using a relatively new project, things like this are to be expected.

Jacques-Peeters · 2023-07-11T09:57:57Z

I want to express that I value all the hard work going into this project. Python was in desperate need for a good language server that integrates with typing.

@Jacques-Peeters I assume there is performance testing, and I assume pathological cases like this will be tested in the future. We’re using a relatively new project, things like this are to be expected.

You're right, this is also the value of the project having constant product updates.

rchiodo · 2023-07-11T22:48:56Z

After some more investigation the commit that caused the problem was not the root cause. It simply put the underlying file system back to the way it should have been.

This bug is reproducible with Pyright, but it doesn't manifest the same way. Instead, it just shows the analysis taking a long time.

[FG] analyzing: c:\Users\rchiodo\source\testing\scanpy\scanpy\tests\test_neighbors.py ...
[FG]   parsing: c:\Users\rchiodo\source\testing\scanpy\scanpy\tests\test_neighbors.py (7ms)
[FG]   binding: c:\Users\rchiodo\source\testing\scanpy\scanpy\tests\test_neighbors.py (2ms)
[FG]   checking: c:\Users\rchiodo\source\testing\scanpy\scanpy\tests\test_neighbors.py (6906ms)
[Info  - 3:47:54 PM] [FG] Long operation: checking: c:\Users\rchiodo\source\testing\scanpy\scanpy\tests\test_neighbors.py (6906ms)
[FG] analyzing: c:\Users\rchiodo\source\testing\scanpy\scanpy\tests\test_neighbors.py (6915ms)
[Info  - 3:47:54 PM] [FG] Long operation: analyzing: c:\Users\rchiodo\source\testing\scanpy\scanpy\tests\test_neighbors.py (6915ms)
[Info  - 3:47:54 PM] SourceFile: Received fs event 'change' for path 'c:\Users\rchiodo\source\testing\scanpy\scanpy\tests\test_neighbors.py'

rchiodo · 2023-07-11T22:52:09Z

@erictraut, the repro steps are in this comment here:
#5474 (comment)

Same repro applies to show it taking a long time in Pyright too.

erictraut · 2023-07-14T09:38:03Z

This was addressed in pyright 1.1.317, which added more aggressive caching for protocol type matching. It is included in this week's "insiders release" of pylance and will be in next week's production release.

It's related to this issue. You can see the measured speedup in various code bases that use numpy.

github-actions bot assigned heejaechang Jul 6, 2023

rchiodo added the bug Something isn't working label Jul 7, 2023

rchiodo assigned rchiodo and unassigned heejaechang Jul 7, 2023

rchiodo mentioned this issue Jul 11, 2023

File Analysis Too Slow #5475

Closed

rchiodo transferred this issue from microsoft/pylance-release Jul 11, 2023

rchiodo removed their assignment Jul 11, 2023

erictraut added needs investigation Requires additional investigation to determine course of action and removed bug Something isn't working labels Jul 12, 2023

erictraut removed the needs investigation Requires additional investigation to determine course of action label Jul 14, 2023

erictraut closed this as completed Jul 14, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Unbearably slow in my code base: https://github.com/scverse/scanpy #5474

Unbearably slow in my code base: https://github.com/scverse/scanpy #5474

rchiodo commented Jul 6, 2023

rchiodo commented Jul 6, 2023

flying-sheep commented Jul 7, 2023 •

edited

Loading

Jacques-Peeters commented Jul 7, 2023 •

edited

Loading

rchiodo commented Jul 7, 2023

rchiodo commented Jul 7, 2023

rchiodo commented Jul 7, 2023

rchiodo commented Jul 7, 2023

rchiodo commented Jul 10, 2023

rchiodo commented Jul 10, 2023

Jacques-Peeters commented Jul 11, 2023

flying-sheep commented Jul 11, 2023

Jacques-Peeters commented Jul 11, 2023

rchiodo commented Jul 11, 2023

rchiodo commented Jul 11, 2023

erictraut commented Jul 14, 2023

Unbearably slow in my code base: https://github.com/scverse/scanpy #5474

Unbearably slow in my code base: https://github.com/scverse/scanpy #5474

Comments

rchiodo commented Jul 6, 2023

rchiodo commented Jul 6, 2023

flying-sheep commented Jul 7, 2023 • edited Loading

Jacques-Peeters commented Jul 7, 2023 • edited Loading

rchiodo commented Jul 7, 2023

rchiodo commented Jul 7, 2023

rchiodo commented Jul 7, 2023

rchiodo commented Jul 7, 2023

rchiodo commented Jul 10, 2023

rchiodo commented Jul 10, 2023

Jacques-Peeters commented Jul 11, 2023

flying-sheep commented Jul 11, 2023

Jacques-Peeters commented Jul 11, 2023

rchiodo commented Jul 11, 2023

rchiodo commented Jul 11, 2023

erictraut commented Jul 14, 2023

flying-sheep commented Jul 7, 2023 •

edited

Loading

Jacques-Peeters commented Jul 7, 2023 •

edited

Loading