Variables viewer causes slowness and instability

[ramajoballester]

I am creating this issue because #8320 and #7069 did not solve the problem.

Environment data

• VS Code: Version: 1.72.2
  Commit: d045a5eda657f4d7b676dedbfa7aab8207f8a075
  Date: 2022-10-12T22:16:26.920Z
  Electron: 19.0.17
  Chromium: 102.0.5005.167
  Node.js: 16.14.2
  V8: 10.2.154.15-electron.0
  OS: Linux x64 5.15.0-52-generic
  Sandboxed: No
• Jupyter Extension version: v2022.9.1202862440
• Python Extension version: v2022.16.1
• OS: Ubuntu 20.04.5 LTS (remote and local)
• Python version: 3.10.6
• Anaconda version: 22.9.0
• Jupyter server running: Remote

Expected behaviour

Normal and fast execution time, given the simplicity of the cell commands. Running the same jupyter kernel (remotely via ssh) in the browser executes every single cell instantaneously.

Actual behaviour

Some cells take a lot of time to execute. I have experienced this behaviour recently after loading a pickle object, but it has happened with other different commands. The time it takes to complete is highly variable and non-repeatable. Memory usage is low.

Waiting for some time before running the next cell avoids this problem (see last cell that executes 1+5 in the expected time). Same in VSCode Insiders.

Logs

With jupyter logging level to verbose. The log corresponds to the screenshots posted:

debug 19:45:55.442: VSCodeNotebookController::handleExecution, Class name = x (started execution)
debug 19:45:55.443: Execute Cell 0 /home/messi/alvaro/loci-sensus/notebooks/first_try.ipynb
debug 19:45:55.444: start the kernel, options.disableUI=false
debug 19:45:55.445: Start Jupyter Session in kernel.ts with disableUI = false
debug 19:45:56.312: Cell 0 executed with state Success
debug 19:45:56.314: VSCodeNotebookController::handleExecution, Class name = x, completed in 872ms, has a falsy return value
debug 19:45:56.532: Executing silently Code (idle) = def _VSCODE_getVariable(what_to_get, is_debugging, *args):\n# Query Jupyter server for the info
debug 19:45:56.548: Executing silently Code (completed) = def _VSCODE_getVariable(what_to_get, is_debugging, *args):\n# Query Jupyter server for the info with 1 output(s)
debug 19:46:03.123: VSCodeNotebookController::handleExecution, Class name = x (started execution)
debug 19:46:03.124: Execute Cell 1 /home/messi/alvaro/loci-sensus/notebooks/first_try.ipynb
debug 19:46:03.124: start the kernel, options.disableUI=false
debug 19:46:03.125: Start Jupyter Session in kernel.ts with disableUI = false
debug 19:46:03.225: Cell 1 executed with state Success
debug 19:46:03.226: VSCodeNotebookController::handleExecution, Class name = x, completed in 103ms, has a falsy return value
debug 19:46:03.568: Executing silently Code (idle) = def _VSCODE_getVariable(what_to_get, is_debugging, *args):\n# Query Jupyter server for the info
debug 19:46:03.584: Executing silently Code (completed) = def _VSCODE_getVariable(what_to_get, is_debugging, *args):\n# Query Jupyter server for the info with 1 output(s)
debug 19:46:04.685: VSCodeNotebookController::handleExecution, Class name = x (started execution)
debug 19:46:04.688: Execute Cell 2 /home/messi/alvaro/loci-sensus/notebooks/first_try.ipynb
debug 19:46:04.688: start the kernel, options.disableUI=false
debug 19:46:04.690: Start Jupyter Session in kernel.ts with disableUI = false
debug 19:46:04.929: Cell 2 executed with state Success
debug 19:46:04.930: VSCodeNotebookController::handleExecution, Class name = x, completed in 245ms, has a falsy return value
debug 19:46:05.083: Executing silently Code (idle) = def _VSCODE_getVariable(what_to_get, is_debugging, *args):\n# Query Jupyter server for the info
debug 19:46:05.100: Executing silently Code (completed) = def _VSCODE_getVariable(what_to_get, is_debugging, *args):\n# Query Jupyter server for the info with 1 output(s)
debug 19:46:06.016: VSCodeNotebookController::handleExecution, Class name = x (started execution)
debug 19:46:06.017: Execute Cell 3 /home/messi/alvaro/loci-sensus/notebooks/first_try.ipynb
debug 19:46:06.017: start the kernel, options.disableUI=false
debug 19:46:06.017: Start Jupyter Session in kernel.ts with disableUI = false
debug 19:46:14.372: Cell 3 executed with state Success
debug 19:46:14.373: VSCodeNotebookController::handleExecution, Class name = x, completed in 8357ms, has a falsy return value
debug 19:46:14.857: Executing silently Code (idle) = def _VSCODE_getVariable(what_to_get, is_debugging, *args):\n# Query Jupyter server for the info
debug 19:46:14.876: Executing silently Code (completed) = def _VSCODE_getVariable(what_to_get, is_debugging, *args):\n# Query Jupyter server for the info with 1 output(s)
debug 19:46:15.489: VSCodeNotebookController::handleExecution, Class name = x (started execution)
debug 19:46:15.491: Execute Cell 4 /home/messi/alvaro/loci-sensus/notebooks/first_try.ipynb
debug 19:46:15.492: start the kernel, options.disableUI=false
debug 19:46:15.492: Start Jupyter Session in kernel.ts with disableUI = false
debug 19:46:15.593: Executing silently Code (busy) = def _VSCODE_getVariable(what_to_get, is_debugging, *args):\n# Query Jupyter server for the info
debug 19:46:24.152: Executing silently Code (completed) = def _VSCODE_getVariable(what_to_get, is_debugging, *args):\n# Query Jupyter server for the info with 1 output(s)
debug 19:46:24.158: Cell 4 executed with state Success
debug 19:46:24.158: VSCodeNotebookController::handleExecution, Class name = x, completed in 8669ms, has a falsy return value
debug 19:46:24.544: Executing silently Code (busy) = def _VSCODE_getVariable(what_to_get, is_debugging, *args):\n# Query Jupyter server for the info
debug 19:46:25.449: VSCodeNotebookController::handleExecution, Class name = x (started execution)
debug 19:46:25.450: Execute Cell 5 /home/messi/alvaro/loci-sensus/notebooks/first_try.ipynb
debug 19:46:25.450: start the kernel, options.disableUI=false
debug 19:46:25.450: Start Jupyter Session in kernel.ts with disableUI = false
debug 19:46:33.376: Executing silently Code (completed) = def _VSCODE_getVariable(what_to_get, is_debugging, *args):\n# Query Jupyter server for the info with 1 output(s)
debug 19:46:33.380: Cell 5 executed with state Success
debug 19:46:33.381: VSCodeNotebookController::handleExecution, Class name = x, completed in 7932ms, has a falsy return value
debug 19:46:33.767: Executing silently Code (busy) = def _VSCODE_getVariable(what_to_get, is_debugging, *args):\n# Query Jupyter server for the info
debug 19:46:34.966: Executing silently Code (busy) = def _VSCODE_getVariable(what_to_get, is_debugging, *args):\n# Query Jupyter server for the info
debug 19:46:35.821: Executing silently Code (busy) = def _VSCODE_getVariable(what_to_get, is_debugging, *args):\n# Query Jupyter server for the info
debug 19:46:35.821: Executing silently Code (busy) = def _VSCODE_getVariable(what_to_get, is_debugging, *args):\n# Query Jupyter server for the info
debug 19:46:42.621: Executing silently Code (completed) = def _VSCODE_getVariable(what_to_get, is_debugging, *args):\n# Query Jupyter server for the info with 1 output(s)
debug 19:46:42.632: Executing silently Code (completed) = def _VSCODE_getVariable(what_to_get, is_debugging, *args):\n# Query Jupyter server for the info with 1 output(s)
debug 19:46:42.642: Executing silently Code (completed) = def _VSCODE_getVariable(what_to_get, is_debugging, *args):\n# Query Jupyter server for the info with 1 output(s)
debug 19:46:42.652: Executing silently Code (completed) = def _VSCODE_getVariable(what_to_get, is_debugging, *args):\n# Query Jupyter server for the info with 1 output(s)
debug 19:46:52.692: VSCodeNotebookController::handleExecution, Class name = x (started execution)
debug 19:46:52.694: Execute Cell 6 /home/messi/alvaro/loci-sensus/notebooks/first_try.ipynb
debug 19:46:52.695: start the kernel, options.disableUI=false
debug 19:46:52.695: Start Jupyter Session in kernel.ts with disableUI = false
debug 19:46:52.738: Executing silently Code (busy) = def _VSCODE_getVariable(what_to_get, is_debugging, *args):\n# Query Jupyter server for the info
debug 19:46:52.768: Executing silently Code (busy) = def _VSCODE_getVariable(what_to_get, is_debugging, *args):\n# Query Jupyter server for the info
debug 19:47:19.626: Executing silently Code (completed) = def _VSCODE_getVariable(what_to_get, is_debugging, *args):\n# Query Jupyter server for the info with 1 output(s)
debug 19:47:19.636: Executing silently Code (completed) = def _VSCODE_getVariable(what_to_get, is_debugging, *args):\n# Query Jupyter server for the info with 1 output(s)
debug 19:47:19.640: Cell 6 executed with state Success
debug 19:47:19.641: VSCodeNotebookController::handleExecution, Class name = x, completed in 26949ms, has a falsy return value
debug 19:47:20.110: Executing silently Code (busy) = def _VSCODE_getVariable(what_to_get, is_debugging, *args):\n# Query Jupyter server for the info
debug 19:47:38.087: Executing silently Code (completed) = def _VSCODE_getVariable(what_to_get, is_debugging, *args):\n# Query Jupyter server for the info with 1 output(s)
debug 19:47:56.332: VSCodeNotebookController::handleExecution, Class name = x (started execution)
debug 19:47:56.334: Execute Cell 7 /home/messi/alvaro/loci-sensus/notebooks/first_try.ipynb
debug 19:47:56.335: start the kernel, options.disableUI=false
debug 19:47:56.336: Start Jupyter Session in kernel.ts with disableUI = false
debug 19:47:56.449: Cell 7 executed with state Success
debug 19:47:56.450: VSCodeNotebookController::handleExecution, Class name = x, completed in 118ms, has a falsy return value
debug 19:47:56.737: Executing silently Code (idle) = def _VSCODE_getVariable(what_to_get, is_debugging, *args):\n# Query Jupyter server for the info
debug 19:47:56.755: Executing silently Code (completed) = def _VSCODE_getVariable(what_to_get, is_debugging, *args):\n# Query Jupyter server for the info with 1 output(s)

[DonJayamanne]

thanks for filling this issue, looks like your have the jupyter variable viewer open, please could you hide that and try this again, id like to check whether that's what's causing the delay.

Just hide the bottom panel, repeat the same steps and provide the logs and screen shot

[ramajoballester]

Thank you so much! It seems to work normally now. I've spent an absurd amount of time reinstalling jupyter in the server to end up just closing the variable viewer 😅

Logs

debug 01:46:12.801: Not executing startup session: Object, code: 
debug 01:46:12.801: Requesting Kernel info
debug 01:46:12.801: Got Kernel info
debug 01:46:12.801: End running kernel initialization, now waiting for idle
debug 01:46:12.801: Waiting for 60000ms idle on (kernel): 8649db69-e9d8-4e81-ae94-81568851a0bc -> idle
debug 01:46:12.801: Finished waiting for idle on (kernel): 8649db69-e9d8-4e81-ae94-81568851a0bc -> idle
debug 01:46:12.801: End running kernel initialization, session is idle
debug 01:46:12.801: Registering commtarget jupyter.widget
debug 01:46:16.763: VSCodeNotebookController::handleExecution, Class name = x (started execution)
debug 01:46:16.763: Execute Cell 3 /home/messi/alvaro/loci-sensus/notebooks/first_try.ipynb
debug 01:46:16.763: start the kernel, options.disableUI=false
debug 01:46:16.763: Start Jupyter Session in kernel.ts with disableUI = false
debug 01:46:17.209: Cell 3 executed with state Success
debug 01:46:17.210: VSCodeNotebookController::handleExecution, Class name = x, completed in 447ms, has a falsy return value
debug 01:46:17.887: VSCodeNotebookController::handleExecution, Class name = x (started execution)
debug 01:46:17.887: Execute Cell 4 /home/messi/alvaro/loci-sensus/notebooks/first_try.ipynb
debug 01:46:17.887: start the kernel, options.disableUI=false
debug 01:46:17.888: Start Jupyter Session in kernel.ts with disableUI = false
debug 01:46:18.006: Cell 4 executed with state Success
debug 01:46:18.007: VSCodeNotebookController::handleExecution, Class name = x, completed in 119ms, has a falsy return value
debug 01:46:18.842: VSCodeNotebookController::handleExecution, Class name = x (started execution)
debug 01:46:18.844: Execute Cell 5 /home/messi/alvaro/loci-sensus/notebooks/first_try.ipynb
debug 01:46:18.845: start the kernel, options.disableUI=false
debug 01:46:18.845: Start Jupyter Session in kernel.ts with disableUI = false
debug 01:46:19.253: Cell 5 executed with state Success
debug 01:46:19.254: VSCodeNotebookController::handleExecution, Class name = x, completed in 412ms, has a falsy return value
debug 01:46:19.545: VSCodeNotebookController::handleExecution, Class name = x (started execution)
debug 01:46:19.545: Execute Cell 6 /home/messi/alvaro/loci-sensus/notebooks/first_try.ipynb
debug 01:46:19.545: start the kernel, options.disableUI=false
debug 01:46:19.545: Start Jupyter Session in kernel.ts with disableUI = false
debug 01:46:19.692: Cell 6 executed with state Success
debug 01:46:19.693: VSCodeNotebookController::handleExecution, Class name = x, completed in 148ms, has a falsy return value
debug 01:46:20.275: VSCodeNotebookController::handleExecution, Class name = x (started execution)
debug 01:46:20.276: Execute Cell 7 /home/messi/alvaro/loci-sensus/notebooks/first_try.ipynb
debug 01:46:20.276: start the kernel, options.disableUI=false
debug 01:46:20.276: Start Jupyter Session in kernel.ts with disableUI = false
debug 01:46:20.370: Cell 7 executed with state Success
debug 01:46:20.371: VSCodeNotebookController::handleExecution, Class name = x, completed in 96ms, has a falsy return value
debug 01:46:21.148: VSCodeNotebookController::handleExecution, Class name = x (started execution)
debug 01:46:21.149: Execute Cell 8 /home/messi/alvaro/loci-sensus/notebooks/first_try.ipynb
debug 01:46:21.149: start the kernel, options.disableUI=false
debug 01:46:21.150: Start Jupyter Session in kernel.ts with disableUI = false
debug 01:46:21.322: Cell 8 executed with state Success
debug 01:46:21.323: VSCodeNotebookController::handleExecution, Class name = x, completed in 175ms, has a falsy return value

[DonJayamanne]

@roblourens /cc

[roblourens]

@DonJayamanne is there another issue that is tracking this issue with the variable viewer?

[DonJayamanne]

another issue that is tracking this issue with the variable viewer?

I don't think we have any open issues

[roblourens]

@ramajoballester can you tell me what kind of data is in info? If it's not private, could you even share the pkl file? Or, a screenshot of the Variables view when it loads might also be helpful. Just trying to understand what exactly caused the issue.