Huge latency executing all comments since update

[drscotthawley]

Searched, didn't see any open issues about this, but a few closed ones about older versions.

My previous version of VSCode worked wonderfully but I kept getting those popups about updating. So mainly in order to get the popups to go away, I downloaded the new version .deb file and installed via dpkg -i. ...But then I noticed, while running remote Jupyter, that even the simplest commands would take 2 to 4 seconds to complete. It doesn't even seem to acknowledge that I pressed Shift-Enter for a the first 2 to 4 seconds, even for just a simple print statement.
It wasn't network latency because if I open up a regular Jupyter notebook and connect via ssh port forwarding, commands complete instantaneously (as my old VSCode version did).

So then I decided to uninstall the new version of VSCode, and go back to the previous version (1.57?),...except now the latency remains even with the old version of VSCode now. I've tried completely uninstalling (and removing ~/.config/Code) each version and re-installing each from scratch, with no longer any success.

...I appreciate that this may be a difficult issue for you to reproduce. I would appreciate any suggestions on this. For now, I'm no longer using VSCode, just going back to regular Jupyter in the browser, but would love to resume VSCode use!

Environment data

• VS Code version: 1.60.2
• Jupyter Extension version (available under the Extensions sidebar): v2021.8.2041215044
• Python Extension version (available under the Extensions sidebar): v2021.9.1246542782
• OS (Windows | Mac | Linux distro) and version: Linux, Pop!_OS (Ubuntu variant) 21.04
• Python and/or Anaconda version: 3.9.5 (local), 3.8 (Remote)
• Type of virtual environment used (N/A | venv | virtualenv | conda | ...): venv
• Jupyter server running: Local | Remote | N/A: Remote
• Remote SSH: v0.65.8

Expected behaviour

Commands should execute quickly or at least provide an indication (as with normal-Jupyter's "*") that the command was received and is running.

Actual behaviour

Commands take 2 to 4 seconds to even register that they were entered, leaving the user to wonder if they actually pressed Run or Shift-Enter.

Steps to reproduce:

[NOTE: Self-contained, minimal reproducing code samples are extremely helpful and will expedite addressing your issue]

1. I appreciate that this may be tricky to reproduce. As I say: I installed the new .deb version. Then everything was slow. Then I reverted to the old version (sorry I don't remember but I believe it was 1.57) and everything is STILL slow. Network latency is not an issue as regular Jupyter notebooks still acknowledge and execute commands instantly, only VSCode Jupyter Extension shows this 2 to 4 second latency.

As uninstalling (& removing ~/.config/Code) reinstalling did not remedy the issue,... I am happy to follow additional directions in order to help diagnose this problem.

Logs

Will follow up with logs in 24 to 48 hours.

Output for Jupyter in the Output panel (View→Output, change the drop-down the upper-right of the Output panel to Jupyter)

XXX

[DavidKutu]

Thanks for filing @drscotthawley. There is something you can share that would help us a lot. Please follow these instructions to measure execution of the extension when you use a command. The generated .cpuprofile would be super helpful.

I hope you get the chance to get back to us.
Thanks a lot in advance.

[DonJayamanne]

Optionally please could you provide the output from Jupyter output panels

[DonJayamanne]

Duplicate of #7855

Please do provide the logs here or in the duplicate issue

[drscotthawley]

Hey folks I've been busy with other things but had been planning to update this today. Too bad it's been closed; I don't know that it's reseolved. @DonJayamanne that new issue #7885 may the duplicate of this one, but see below.

This issue seems to be limited to "Remote Jupyter", which might be regarded as a separate package. If so, keep this issue closed and ignore what follows. Running vscode-jupyter locally, I am unable to duplicate the problem.
For the sake of definiteness, I will describe the issues using this sample notebook: https://github.com/drscotthawley/espiownage/blob/master/nbs/count_in_crops_cyclegan.ipynb
Though I'm not choosing this notebook for any special reason; I was noticing issues with a variety of notebooks.

One example of the problem occurs in this notebook at the cell that defines a fastai Learner, where the code reads...

learn = cnn_learner(dls, resnet34, n_out=1, y_range=y_range, metrics=[mae, acc_reg05,acc_reg1,acc_reg15,acc_reg2], loss_func=MSELossFlat(), opt_func=opt)

Running on local VSCode Jupyter this cell takes 0.4s to execute, but it takes 3.8 seconds via Remote Jupyter connected via ssh to a computer in the same physical location connected by wifi suffering no known network issues. There is no significant output from this cell that might delay communication. (Furthermore, the learner will have already downloaded the ResNet34 weights on a previous run, so that is not the cause of the delay). Prior to updating my VSCode, no such latency was observed.

It's also possible that the issue is not with Jupyter or with Remote Jupyter but actually with the SSH extension.

Logs.

Heres the View > Outputs > Jupyter, when running Remote Juptyer in VSCode up to the cell defining the Learner:

Info 2021-10-07 13:50:49: Execute Cells request 1 2
Info 2021-10-07 13:50:49: Execute Cell 2 file:///home/shawley/espi-work/count_in_crops_fake2.ipynb
Info 2021-10-07 13:50:50: Notebook Session status file:///home/shawley/espi-work/count_in_crops_fake2.ipynb # Busy
Info 2021-10-07 13:50:50: Notebook Session status file:///home/shawley/espi-work/count_in_crops_fake2.ipynb # Idle
Info 2021-10-07 13:50:50: Execute Cells request 1 3
Info 2021-10-07 13:50:50: Execute Cell 3 file:///home/shawley/espi-work/count_in_crops_fake2.ipynb
Info 2021-10-07 13:50:50: Notebook Session status file:///home/shawley/espi-work/count_in_crops_fake2.ipynb # Busy
Info 2021-10-07 13:50:51: Execute Cells request 1 5
Info 2021-10-07 13:50:51: Execute Cell 5 file:///home/shawley/espi-work/count_in_crops_fake2.ipynb
Info 2021-10-07 13:50:53: Execute Cells request 1 7
Info 2021-10-07 13:50:53: Execute Cell 7 file:///home/shawley/espi-work/count_in_crops_fake2.ipynb
Info 2021-10-07 13:50:54: Execute Cells request 1 8
Info 2021-10-07 13:50:54: Execute Cell 8 file:///home/shawley/espi-work/count_in_crops_fake2.ipynb
Info 2021-10-07 13:50:54: Notebook Session status file:///home/shawley/espi-work/count_in_crops_fake2.ipynb # Idle
Info 2021-10-07 13:50:55: Notebook Session status file:///home/shawley/espi-work/count_in_crops_fake2.ipynb # Busy
Info 2021-10-07 13:50:57: Notebook Session status file:///home/shawley/espi-work/count_in_crops_fake2.ipynb # Idle
Info 2021-10-07 13:50:57: Notebook Session status file:///home/shawley/espi-work/count_in_crops_fake2.ipynb # Busy
Info 2021-10-07 13:50:57: Notebook Session status file:///home/shawley/espi-work/count_in_crops_fake2.ipynb # Idle
Info 2021-10-07 13:50:57: Notebook Session status file:///home/shawley/espi-work/count_in_crops_fake2.ipynb # Busy
Info 2021-10-07 13:50:58: Notebook Session status file:///home/shawley/espi-work/count_in_crops_fake2.ipynb # Idle
Info 2021-10-07 13:50:58: Execute Cells request 1 9
Info 2021-10-07 13:50:58: Execute Cell 9 file:///home/shawley/espi-work/count_in_crops_fake2.ipynb
Info 2021-10-07 13:50:59: Notebook Session status file:///home/shawley/espi-work/count_in_crops_fake2.ipynb # Busy
Info 2021-10-07 13:50:59: Notebook Session status file:///home/shawley/espi-work/count_in_crops_fake2.ipynb # Idle
Info 2021-10-07 13:51:00: Execute Cells request 1 10
Info 2021-10-07 13:51:00: Execute Cell 10 file:///home/shawley/espi-work/count_in_crops_fake2.ipynb
Info 2021-10-07 13:51:00: Notebook Session status file:///home/shawley/espi-work/count_in_crops_fake2.ipynb # Busy
Info 2021-10-07 13:51:00: Notebook Session status file:///home/shawley/espi-work/count_in_crops_fake2.ipynb # Idle
Info 2021-10-07 13:51:02: Execute Cells request 1 12
Info 2021-10-07 13:51:02: Execute Cell 12 file:///home/shawley/espi-work/count_in_crops_fake2.ipynb
Info 2021-10-07 13:51:02: Notebook Session status file:///home/shawley/espi-work/count_in_crops_fake2.ipynb # Busy
Info 2021-10-07 13:51:02: Notebook Session status file:///home/shawley/espi-work/count_in_crops_fake2.ipynb # Idle
Info 2021-10-07 13:51:04: Execute Cells request 1 13
Info 2021-10-07 13:51:04: Execute Cell 13 file:///home/shawley/espi-work/count_in_crops_fake2.ipynb
Info 2021-10-07 13:51:04: Notebook Session status file:///home/shawley/espi-work/count_in_crops_fake2.ipynb # Busy
Info 2021-10-07 13:51:11: Notebook Session status file:///home/shawley/espi-work/count_in_crops_fake2.ipynb # Idle
Info 2021-10-07 13:52:35: Execute Cells request 1 14
Info 2021-10-07 13:52:35: Execute Cell 14 file:///home/shawley/espi-work/count_in_crops_fake2.ipynb
Info 2021-10-07 13:52:35: Notebook Session status file:///home/shawley/espi-work/count_in_crops_fake2.ipynb # Busy
Info 2021-10-07 13:52:36: Notebook Session status file:///home/shawley/espi-work/count_in_crops_fake2.ipynb # Idle
Info 2021-10-07 13:52:37: Execute Cells request 1 15
Info 2021-10-07 13:52:37: Execute Cell 15 file:///home/shawley/espi-work/count_in_crops_fake2.ipynb
Info 2021-10-07 13:52:37: Notebook Session status file:///home/shawley/espi-work/count_in_crops_fake2.ipynb # Busy
Info 2021-10-07 13:52:38: Notebook Session status file:///home/shawley/espi-work/count_in_crops_fake2.ipynb # Idle
Info 2021-10-07 13:52:40: Execute Cells request 1 17
Info 2021-10-07 13:52:40: Execute Cell 17 file:///home/shawley/espi-work/count_in_crops_fake2.ipynb
Info 2021-10-07 13:52:40: Notebook Session status file:///home/shawley/espi-work/count_in_crops_fake2.ipynb # Busy
Info 2021-10-07 13:52:40: Notebook Session status file:///home/shawley/espi-work/count_in_crops_fake2.ipynb # Idle
Info 2021-10-07 13:52:41: Execute Cells request 1 18
Info 2021-10-07 13:52:41: Execute Cell 18 file:///home/shawley/espi-work/count_in_crops_fake2.ipynb
Info 2021-10-07 13:52:41: Notebook Session status file:///home/shawley/espi-work/count_in_crops_fake2.ipynb # Busy
Info 2021-10-07 13:52:45: Notebook Session status file:///home/shawley/espi-work/count_in_crops_fake2.ipynb # Idle

I'll post the cpu profile next.

[drscotthawley]

Having problems figuring out were to find "Developer" in order to perform the profiling. Just submitted a feature request for more explicit documentation of the instructions that @DavidKutu pointed me to.

[drscotthawley]

...Ok found it via View > Command Pallette... > Developer: Running Extensions.
Attaching CPU profile to this comment.

CPU-20211007T193402.334Z.cpuprofile.txt