The Pylance server crashed 5 times in the last 3 minutes in a .py file + .ipynb opened in editor #3510

kryzhikov · 2022-10-20T10:54:08Z

Environment data

Language Server version: v2022.10.30
OS and version: linux + ssh
Python version (& distribution if applicable, e.g. Anaconda): Miniconda 4.12.0, python 3.6

Code Snippet

Repro Steps

Connect to remote server
Open python file
Open ipynb file in same editor window in other tab
Both files use same conda env

Expected behavior

Pylance working smoothly

Actual behavior

Pylance crashes multiple times, if closing .py file or .ipynb file, errors disappear

Logs

Short logs

[Info  - 6:42:39 AM] (1686) Pylance language server 2022.10.30 (pyright 50e12b4b) starting
[Info  - 6:42:39 AM] (1686) Server root directory: /lxhome/ryzhikok/.vscode-server/extensions/ms-python.vscode-pylance-2022.10.30/dist
[Info  - 6:42:39 AM] (1686) Starting service instance "report_processor"
[Info  - 6:42:39 AM] (1686) Notebook support: LSP
[Info  - 6:42:39 AM] (1686) Interactive window support: LSP
[Info  - 6:42:39 AM] (1686) No configuration file found.
[Info  - 6:42:39 AM] (1686) No pyproject.toml file found.
[Info  - 6:42:39 AM] (1686) Setting pythonPath for service "report_processor": "/lxhome/ryzhikok/miniconda3/envs/new_base/bin/python"
[Warn  - 6:42:39 AM] (1686) stubPath /lxhome/ryzhikok/dev/report_processor/typings is not a valid directory.
[Info  - 6:42:39 AM] (1686) Assuming Python version 3.6
[Info  - 6:42:39 AM] (1686) Assuming Python platform Linux
[Info  - 6:42:39 AM] (1686) Searching for source files
[Info  - 6:42:39 AM] (1686) Found 4 source files
[Info  - 6:42:39 AM] (1686) Starting service instance "/lxhome/ryzhikok/dev/report_processor/Report_processor.ipynb"
[Info  - 6:42:39 AM] (1686) Background analysis(1) root directory: /lxhome/ryzhikok/.vscode-server/extensions/ms-python.vscode-pylance-2022.10.30/dist
[Info  - 6:42:39 AM] (1686) Background analysis(1) started
[Info  - 6:42:39 AM] (1686) No configuration file found.
[Info  - 6:42:39 AM] (1686) No pyproject.toml file found.
[Info  - 6:42:39 AM] (1686) Setting pythonPath for service "/lxhome/ryzhikok/dev/report_processor/Report_processor.ipynb": "/lxhome/ryzhikok/miniconda3/envs/new_base/bin/python"
[Warn  - 6:42:39 AM] (1686) stubPath /lxhome/ryzhikok/dev/report_processor/typings is not a valid directory.
[Info  - 6:42:40 AM] (1686) Assuming Python version 3.6
[Info  - 6:42:40 AM] (1686) Assuming Python platform Linux
[Info  - 6:42:40 AM] (1686) Searching for source files
[Info  - 6:42:40 AM] (1686) Found 4 source files
[Info  - 6:42:40 AM] (1686) Background analysis(3) root directory: /lxhome/ryzhikok/.vscode-server/extensions/ms-python.vscode-pylance-2022.10.30/dist
[Info  - 6:42:40 AM] (1686) Background analysis(3) started
[Info  - 6:42:40 AM] (1686) Indexer background runner(2) root directory: /lxhome/ryzhikok/.vscode-server/extensions/ms-python.vscode-pylance-2022.10.30/dist (index)
[Info  - 6:42:40 AM] (1686) Indexing(2) started
[Info  - 6:42:42 AM] (1686) [BG(3)] Long operation: analyzing: /lxhome/ryzhikok/dev/report_processor/Report_processor.ipynb:pylance-notebook-cell:W0sdnNjb2RlLXJlbW90ZQ==.py (2255ms)
[Info  - 6:42:44 AM] (1686) [BG(1)] Long operation: checking: /lxhome/ryzhikok/dev/report_processor/plots.py (4078ms)
[Info  - 6:42:44 AM] (1686) [BG(1)] Long operation: analyzing: /lxhome/ryzhikok/dev/report_processor/plots.py (4440ms)
[Info  - 6:42:47 AM] (1686) [IDX(2)] Long operation: index execution environment /lxhome/ryzhikok/dev/report_processor (5727ms)
[Info  - 6:42:47 AM] (1686) [IDX(2)] Long operation: index libraries /lxhome/ryzhikok/dev/report_processor (6996ms)
[Info  - 6:42:47 AM] (1686) Indexer done(2). indexed 644 files
Error: request cancelled
    at t.throwIfCancellationRequested (/lxhome/ryzhikok/.vscode-server/extensions/ms-python.vscode-pylance-2022.10.30/dist/pyright-internal/src/common/cancellationUtils.ts:42:15)
    at MessagePort.<anonymous> (/lxhome/ryzhikok/.vscode-server/extensions/ms-python.vscode-pylance-2022.10.30/dist/server.bundle.js:1:394287)
    at MessagePort.[nodejs.internal.kHybridDispatch] (node:internal/event_target:647:20)
    at MessagePort.exports.emitMessage (node:internal/per_context/messageport:23:28)
[Info  - 6:42:47 AM] Connection to server got closed. Server will restart.

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

benchoi93 · 2022-10-20T14:35:59Z

I got similar error on latest version.
Installing previous versions of Pylance fixed the problem

tautomer · 2022-10-26T15:54:57Z

Observed exactly the same thing #3453 (comment)

heejaechang · 2022-10-26T17:54:30Z

@benchoi93 yours seems not the same one as this issue. can you open new issue with log?

rchiodo · 2022-10-26T18:32:48Z

@tautomer and @kryzhikov what is this setting?

And this one:

Can you make sure those are both enabled? Otherwise, there are incompatibilities between the jupyter extension and the pylance extension.

rchiodo · 2022-10-26T18:37:17Z

Oh and make sure they're enabled on the remote machine. I'm testing this with Codespaces, so it looks like this for me in the UI

rchiodo · 2022-10-26T18:48:37Z

Additionally, if you upgrade the jupyter extension, the python extension, and the pylance extension to the preview versions, this problem should go away. These settings are not allowed in newer versions and are always true.

tautomer · 2022-10-26T18:51:39Z

@tautomer and @kryzhikov what is this setting?

And this one:

Can you make sure those are both enabled? Otherwise, there are incompatibilities between the jupyter extension and the pylance extension.

IIRC, I never checked these two settings myself, but they are both enabled.

Jupyter extension is latest stable (v2022.9.1202862440). All recent pylance versions seem to have the problem. I'm using v2022.9.10 right now which has been working fine since this morning.

Additionally, if you upgrade the jupyter extension, the python extension, and the pylance extension to the preview versions, this problem should go away. These settings are not allowed in newer versions and are always true.

I never tried pre-release for all 3, only pylance. Let me test this out this afternoon.

rchiodo · 2022-10-26T20:45:24Z

I'm trying to repro and it doesn't seem to crash. @tautomer can you share your python file and the notebook you used? And what actions you took after opening? It sounded like you just needed the two files open for the crash to occur?

rchiodo · 2022-10-26T20:52:50Z

Here's exactly what I tried:

tautomer · 2022-10-27T02:32:05Z

I'm trying to repro and it doesn't seem to crash. @tautomer can you share your python file and the notebook you used? And what actions you took after opening? It sounded like you just needed the two files open for the crash to occur?

Hi Rich, thanks for the test. I think we can narrow down the problem even more. Another requirement to trigger the problem might be a big enough file structure.

I have recorded my screen, but I'm not sure if I can share it here. National lab policies... Let me ask someone tomorrow.

To briefly summarize, here is what I have for test

big_folder/ethene_with_nacr/long/test/1.ipynb has one line code import numpy as np
big_folder/ethene_with_nacr/long/test/1.py has one line code import argparse

big_folder is 38 GB in total, with around 100K files.
If I open this folder as the workspace, and then open ethene_with_nacr/long/test/1.ipynb and ethene_with_nacr/long/test/1.py side by side, latest pylance always crashes.

The log right before crash is like

[Info  - 8:20:19 PM] (646582) Searching for source files
[Info  - 8:20:25 PM] (646582) Found 299 source files
[Info  - 8:20:25 PM] (646582) Indexer background runner(2) root directory: /vast/home/lix/.vscode-server/extensions/ms-python.vscode-pylance-2022.10.40/dist (index)
[Info  - 8:20:25 PM] (646582) Indexing(2) started
[Info  - 8:20:25 PM] (646582) [IDX(2)] Long operation: index execution environment /project/ml4chem/xinyang (5099ms)
[Info  - 8:20:25 PM] (646582) [IDX(2)] Long operation: index libraries /project/ml4chem/xinyang (6079ms)
[Info  - 8:20:25 PM] (646582) Indexer done(2). indexed 639 files
Error: request cancelled
    at t.throwIfCancellationRequested (/vast/home/lix/.vscode-server/extensions/ms-python.vscode-pylance-2022.10.40/dist/pyright-internal/src/common/cancellationUtils.ts:42:15)
    at MessagePort.<anonymous> (/vast/home/lix/.vscode-server/extensions/ms-python.vscode-pylance-2022.10.40/dist/server.bundle.js:1:437602)
    at MessagePort.[nodejs.internal.kHybridDispatch] (node:internal/event_target:647:20)
    at MessagePort.exports.emitMessage (node:internal/per_context/messageport:23:28)
[Info  - 8:20:25 PM] Connection to server got closed. Server will restart.

/project/ml4chem/xinyang is the big_folder.

If I open any child directory, it's fine. For example, the ethene_with_nacr folder is 18 GB in size with around 30K files. Using this folder as the workspace will be fine.

I just tested another huge folder on a different cluster and observed the same problem.

For comparison, the older version 2022.9.10

Info  - 8:28:07 PM] (2620248) Searching for source files
[Info  - 8:28:07 PM] (2620248) Found 1 source file
[Info  - 8:28:07 PM] (2620248) Indexer background runner(3) root directory: /vast/home/lix/.vscode-server/extensions/ms-python.vscode-pylance-2022.9.10/dist (index)
[Info  - 8:28:07 PM] (2620248) Indexing(3) started
[Info  - 8:28:07 PM] (2620248) Indexer background runner(4) root directory: /vast/home/lix/.vscode-server/extensions/ms-python.vscode-pylance-2022.9.10/dist (index)
[Info  - 8:28:07 PM] (2620248) Indexing(4) started
[Info  - 8:28:14 PM] (2620248) [IDX(3)] Long operation: index execution environment /projects/ml4chem/xinyang (5578ms)
[Info  - 8:28:14 PM] (2620248) [IDX(3)] Long operation: index libraries /projects/ml4chem/xinyang (6787ms)
[Info  - 8:28:14 PM] (2620248) Indexer done(3). indexed 628 files
[Info  - 8:28:14 PM] (2620248) [IDX(4)] Long operation: index execution environment /projects/ml4chem/xinyang/ethene_with_nacr/long/test (5591ms)
[Info  - 8:28:14 PM] (2620248) [IDX(4)] Long operation: index libraries /projects/ml4chem/xinyang/ethene_with_nacr/long/test (6577ms)
[Info  - 8:28:14 PM] (2620248) Indexer done(4). indexed 628 files

It looks to me that newer versions somehow decides to restart the server when indexing takes too long. Because the folder is big, indexing is always slow, pylance will keep restart until hitting 5 times and crash. However, if only one file is opened, the log from newer pylance looks exactly the same.

rchiodo · 2022-10-27T17:03:18Z

Hmm, seems like it needs something large enough that it decides to cancel indexing. I can probably artificially cause that.

tautomer · 2022-10-27T17:44:40Z

Hmm, seems like it needs something large enough that it decides to cancel indexing. I can probably artificially cause that.

Yep, I couldn't reproduce this problem either only my local computer, unless manually create lots of dummy files.

Got the permission to upload recordings if they help at all.

Here is what happens when opening the grand grandparent folder (38 GB) with notebook and python side by side.

Screen.Recording.2022-10-26.at.7.38.56.PM.mov

Same thing for the parent of grandparent (18 GB). No problem at all.

Screen.Recording.2022-10-26.at.7.41.08.PM.mov

Or open the the grand grandparent folder, but only opening one notebook. No crash, but I think once you open another file in group 2, it will crash eventually, as pylance will decide to cancel indexing. I could be wrong here.

Screen.Recording.2022-10-26.at.7.41.43.PM.mov

rchiodo · 2022-10-27T21:35:16Z

@tautomer, when it crashes can you upload the pylance language server log? The crash is happening in worker when handling a message.

Error: request cancelled
    at t.throwIfCancellationRequested (/vast/home/lix/.vscode-server/extensions/ms-python.vscode-pylance-2022.10.40/dist/pyright-internal/src/common/cancellationUtils.ts:42:15)
    at MessagePort.<anonymous> (/vast/home/lix/.vscode-server/extensions/ms-python.vscode-pylance-2022.10.40/dist/server.bundle.js:1:437602)
    at MessagePort.[nodejs.internal.kHybridDispatch] (node:internal/event_target:647:20)
    at MessagePort.exports.emitMessage (node:internal/per_context/messageport:23:28)

It would really help if I knew what the message was. The log should have it somewhere above where the error is output.

It should look something like this:

(16827) Background analysis message: getDiagnosticsForRange

You have to set logging to full trace first though.

rchiodo · 2022-10-27T21:48:09Z

I'm still having trouble reproing. Even with opening a huge folder with 1000s of python files.

tautomer · 2022-10-27T22:03:20Z

I'm still having trouble reproing. Even with opening a huge folder with 1000s of python files.

Here you go. A log with full trace from window loading till pylance crashes.
pylance.log

I suspect it's not just python files, but the total number of all file? I don't really know how pylance's indexer works though, just my guess. Another huge directory has (I think) only 3 python files indexed, but many other files are in the folder. pylance crashes as well. (I can double check this tonight.)

I also did a test with one of my conda environment folders. There are almost 28K python files. Indexing is slow as well and hit 2000-file limit, but no crashes.

rchiodo · 2022-10-27T23:04:42Z

Thanks that helps. It looks like it's getting semantic tokens.

heejaechang · 2022-10-28T06:41:52Z

can you set "python.analysis.indexing": false in your settings.json and see whether it still repro?

mabynke · 2022-10-28T10:00:53Z

I believe I have the same problem.
My working directory has ~60 000 files (most of which are non-python files in symlinked folders).
The Pylance server crashes 5 times and is stopped from restarting. It seems to happen if a notebook and a .py file are open side by side when Pylance launces. It does not happen if (1) no files are open, (2) only a notebook is open, (3) only a .py file is open, (4) no files are open or (5) a notebook and a .py file are open as two tabs in the same editor group (not side by side).
When I close the notebook while Pylance is still in its crash-restart loop, the next restart succeeds, and the loop stops.
With "python.analysis.indexing": false it seems I can not reproduce the issue.

I don't know if this is related, but Pylance is incredibly slow at parsing my .py file with ~600 lines, taking about 10 seconds for each change I do in the file, often queueing up and resulting in very long waiting times. This mostly goes away when setting "python.analysis.indexing": false.

heejaechang · 2022-10-28T10:12:59Z

I don't know if this is related, but Pylance is incredibly slow at parsing my .py file with ~600 lines, taking about 10 seconds for each change I do in the file, often queueing up and resulting in very long waiting times. This mostly goes away when setting "python.analysis.indexing": false.

for the issue above, can you provide us some logs as described in the troubleshooting guide?

mabynke · 2022-10-28T12:04:29Z

Unfortunately, now that I try again in order to provide a log, I am inexplicably unable to reproduce the slowness anymore, even though this has been a problem for a while. It now uses only 2 to 3 seconds to react to my edit. I can come back to this if the problem returns.

In the meantime, here is the log from a run I did showcasing the original problem (the crash) which can still be reproduced reliably: pylance_log_crash_2.txt. Here, I launched VS Code with a notebook and a .py file side by side, and the Pylance server crashed 5 times.

rchiodo · 2022-10-28T16:14:19Z

@tautomer we have a potential fix. If you'd like to try it out, I can send you a private vsix with the bits in it. Please contact me at my github id at microsoft.com if that's okay with you.

tautomer · 2022-10-28T16:34:46Z

can you set "python.analysis.indexing": false in your settings.json and see whether it still repro?

No more crashes after setting this false.

@tautomer we have a potential fix. If you'd like to try it out, I can send you a private vsix with the bits in it. Please contact me at my github id at microsoft.com if that's okay with you.

Sent.

rchiodo · 2022-10-28T16:37:32Z

@tautomer, in case it's not obvious, please turn indexing back on in the private I sent you.

rchiodo · 2022-11-03T01:06:57Z

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

github-actions bot added the triage-needed label Oct 20, 2022

luabud added needs investigation Could be an issue - needs investigation and removed triage-needed labels Oct 20, 2022

luabud assigned heejaechang Oct 20, 2022

iann838 mentioned this issue Oct 21, 2022

Pylance becomes increasingly slow and unresponsive over time #3514

Closed

rchiodo assigned rchiodo and unassigned heejaechang Oct 26, 2022

rchiodo added waiting for user response Requires more information from user and removed needs investigation Could be an issue - needs investigation labels Oct 26, 2022

rchiodo added needs investigation Could be an issue - needs investigation and removed waiting for user response Requires more information from user labels Oct 27, 2022

rchiodo closed this as completed Nov 3, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

The Pylance server crashed 5 times in the last 3 minutes in a .py file + .ipynb opened in editor #3510

The Pylance server crashed 5 times in the last 3 minutes in a .py file + .ipynb opened in editor #3510

kryzhikov commented Oct 20, 2022

benchoi93 commented Oct 20, 2022

tautomer commented Oct 26, 2022

heejaechang commented Oct 26, 2022

rchiodo commented Oct 26, 2022 •

edited

Loading

rchiodo commented Oct 26, 2022

rchiodo commented Oct 26, 2022

tautomer commented Oct 26, 2022 •

edited

Loading

rchiodo commented Oct 26, 2022

rchiodo commented Oct 26, 2022

tautomer commented Oct 27, 2022 •

edited

Loading

rchiodo commented Oct 27, 2022

tautomer commented Oct 27, 2022

rchiodo commented Oct 27, 2022

rchiodo commented Oct 27, 2022

tautomer commented Oct 27, 2022 •

edited

Loading

rchiodo commented Oct 27, 2022

heejaechang commented Oct 28, 2022

mabynke commented Oct 28, 2022

heejaechang commented Oct 28, 2022

mabynke commented Oct 28, 2022

rchiodo commented Oct 28, 2022

tautomer commented Oct 28, 2022

rchiodo commented Oct 28, 2022

rchiodo commented Nov 3, 2022 •

edited

Loading

The Pylance server crashed 5 times in the last 3 minutes in a .py file + .ipynb opened in editor #3510

The Pylance server crashed 5 times in the last 3 minutes in a .py file + .ipynb opened in editor #3510

Comments

kryzhikov commented Oct 20, 2022

Environment data

Code Snippet

Repro Steps

Expected behavior

Actual behavior

Logs

benchoi93 commented Oct 20, 2022

tautomer commented Oct 26, 2022

heejaechang commented Oct 26, 2022

rchiodo commented Oct 26, 2022 • edited Loading

rchiodo commented Oct 26, 2022

rchiodo commented Oct 26, 2022

tautomer commented Oct 26, 2022 • edited Loading

rchiodo commented Oct 26, 2022

rchiodo commented Oct 26, 2022

tautomer commented Oct 27, 2022 • edited Loading

rchiodo commented Oct 27, 2022

tautomer commented Oct 27, 2022

rchiodo commented Oct 27, 2022

rchiodo commented Oct 27, 2022

tautomer commented Oct 27, 2022 • edited Loading

rchiodo commented Oct 27, 2022

heejaechang commented Oct 28, 2022

mabynke commented Oct 28, 2022

heejaechang commented Oct 28, 2022

mabynke commented Oct 28, 2022

rchiodo commented Oct 28, 2022

tautomer commented Oct 28, 2022

rchiodo commented Oct 28, 2022

rchiodo commented Nov 3, 2022 • edited Loading

rchiodo commented Oct 26, 2022 •

edited

Loading

tautomer commented Oct 26, 2022 •

edited

Loading

tautomer commented Oct 27, 2022 •

edited

Loading

tautomer commented Oct 27, 2022 •

edited

Loading

rchiodo commented Nov 3, 2022 •

edited

Loading