microsoft / vscode-jupyter

VS Code Jupyter extension
https://marketplace.visualstudio.com/items?itemName=ms-toolsai.jupyter
MIT License
1.26k stars 277 forks source link

Running cell in Interactive Window gets stuck on "Pending" #15840

Open goldrik opened 2 weeks ago

goldrik commented 2 weeks ago

Environment data

Info

I am trying to run cells from a regular python (.py, not .ipynb) file. Sometimes, I run code in the cells directly.

Jupyter › Interactive Window: Creation Mode is set to Multiple

Expected behaviour

Code should run immediately.

Actual behaviour

SOMETIMES (this behavior is very inconsistent), the cell gets stuck on "Pending" for some period of time before executing. In the logs below, the cell was Pending for 5+ minutes before it finally executed.

Steps to reproduce:

I had run all the cells in my file at once. Then I ran the following cell (%%timeit) in the Interactive Window. Half a minute later, while the cell was still pending, I ran another cell. Five minutes later, I finally got output.

Screenshot 2024-07-10 at 11 35 33 AM 3

Now can I run cells normally, but after a bit the problem occurs again, randomly.

It doesnt need to be this way, sometimes the pending behavior occurs when I send a code cell (from my file) to run. It can be literally any code, as simple as printing a variable. The pending time varies a lot.

Logs

11:34:26.108 [debug] Code execution cancelled by extension ms-toolsai.jupyter 11:34:26.108 [debug] Code execution cancelled by extension ms-toolsai.jupyter 11:34:26.108 [debug] Jupyter completion time: 1109 11:34:29.745 [debug] Code execution cancelled by extension ms-toolsai.jupyter 11:34:29.745 [debug] Code execution cancelled by extension ms-toolsai.jupyter 11:34:29.745 [debug] Jupyter completion time: 124 11:34:33.843 [debug] Handle Execution of Cells 31 for Interactive-1.interactive 11:34:33.843 [trace] Cell Index:31 sent to kernel 11:34:53.548 [debug] Code execution cancelled by extension ms-toolsai.jupyter 11:34:53.548 [debug] Code execution cancelled by extension ms-toolsai.jupyter 11:34:53.548 [debug] Jupyter completion time: 264 11:34:53.554 [debug] Handle Execution of Cells 32 for Interactive-1.interactive 11:40:20.889 [trace] Executing silently Code (completed) = def _VSCODE_getVariable(what_to_get, is_debugging, args):\n# Query Jupyter server for the info with 1 output(s) 11:40:20.927 [trace] Executing silently Code (completed) = def _VSCODE_getVariable(what_to_get, is_debugging, args):\n# Query Jupyter server for the info with 1 output(s) 11:40:20.967 [trace] Executing silently Code (completed) = def _VSCODE_getVariable(what_to_get, is_debugging, args):\n# Query Jupyter server for the info with 1 output(s) 11:40:21.003 [trace] Executing silently Code (completed) = def _VSCODE_getVariable(what_to_get, is_debugging, args):\n# Query Jupyter server for the info with 1 output(s) 11:40:21.040 [trace] Executing silently Code (completed) = def _VSCODE_getVariable(what_to_get, is_debugging, args):\n# Query Jupyter server for the info with 1 output(s) 11:40:21.078 [trace] Executing silently Code (completed) = def _VSCODE_getVariable(what_to_get, is_debugging, args):\n# Query Jupyter server for the info with 1 output(s) 11:40:21.115 [trace] Executing silently Code (completed) = def _VSCODE_getVariable(what_to_get, is_debugging, args):\n# Query Jupyter server for the info with 1 output(s) 11:40:21.152 [trace] Executing silently Code (completed) = def _VSCODE_getVariable(what_to_get, is_debugging, args):\n# Query Jupyter server for the info with 1 output(s) 11:40:21.168 [trace] Start cell 31 execution @ 1720626021168 (clear output) 11:40:21.168 [debug] Kernel acknowledged execution of cell 31 @ 1720626021168 11:40:35.891 [trace] Cell 31 completed in 14.723s (start: 1720626021168, end: 1720626035891) 11:40:35.891 [trace] Cell 31 executed successfully 11:40:35.892 [trace] Cell Index:32 sent to kernel 11:40:35.904 [trace] Executing silently Code (idle) = def _VSCODE_getVariable(what_to_get, is_debugging, args):\n# Query Jupyter server for the info 11:40:35.908 [trace] Start cell 32 execution @ 1720626035908 (clear output) 11:40:35.908 [debug] Kernel acknowledged execution of cell 32 @ 1720626035908 11:40:35.911 [trace] Cell 32 completed in 0.003s (start: 1720626035908, end: 1720626035911) 11:40:35.911 [trace] Cell 32 executed successfully 11:40:35.936 [trace] Executing silently Code (completed) = def _VSCODE_getVariable(what_to_get, is_debugging, args):\n# Query Jupyter server for the info with 1 output(s) 11:44:26.948 [trace] Executing silently Code (idle) = def _VSCODE_getVariable(what_to_get, is_debugging, args):\n# Query Jupyter server for the info 11:44:26.988 [trace] Executing silently Code (completed) = def _VSCODE_getVariable(what_to_get, is_debugging, args):\n# Query Jupyter server for the info with 1 output(s)

goldrik commented 2 weeks ago

This happened again just now, this time while running a code cell from my file. The first section is before I ran the cell, when I had no issues. The second section has the logs after running the cell, which is when it hung for a few minutes.

Here are the logs BEFORE

12:01:03.557 [info] Generated code for 34 = with 100 lines 12:01:03.562 [trace] Cell Index:34 sent to kernel 12:01:03.572 [trace] Start cell 34 execution @ 1720627263572 (clear output) 12:01:03.572 [debug] Kernel acknowledged execution of cell 34 @ 1720627263572 12:01:06.021 [trace] Executing silently Code (busy) = def _VSCODE_getVariable(what_to_get, is_debugging, args):\n# Query Jupyter server for the info 12:01:09.039 [trace] Cell 34 completed in 5.467s (start: 1720627263572, end: 1720627269039) 12:01:09.039 [trace] Cell 34 executed successfully 12:01:09.076 [trace] Executing silently Code (completed) = def _VSCODE_getVariable(what_to_get, is_debugging, args):\n# Query Jupyter server for the info with 1 output(s) 12:01:44.460 [trace] Executing silently Code (busy) = def _VSCODE_getVariable(what_to_get, is_debugging, args):\n# Query Jupyter server for the info 12:01:45.742 [trace] Executing silently Code (busy) = def _VSCODE_getVariable(what_to_get, is_debugging, args):\n# Query Jupyter server for the info 12:01:48.446 [debug] CodeLensFactory: Generating new code lenses for version 32 of document file://proton/AlgorithmGroup/Users/~/projects/InstrumentDifferences/python/script_usepartial.py for commands jupyter.runcell, jupyter.runallcellsabove, jupyter.debugcell, jupyter.debugcontinue, jupyter.debugstop, jupyter.debugstepover 12:01:48.794 [debug] CodeLensFactory: Generating new code lenses for version 33 of document file://proton/AlgorithmGroup/Users/~/projects/InstrumentDifferences/python/script_usepartial.py for commands jupyter.runcell, jupyter.runallcellsabove, jupyter.debugcell, jupyter.debugcontinue, jupyter.debugstop, jupyter.debugstepover 12:01:49.305 [debug] CodeLensFactory: Generating new code lenses for version 34 of document file://proton/AlgorithmGroup/Users/~/projects/InstrumentDifferences/python/script_usepartial.py for commands jupyter.runcell, jupyter.runallcellsabove, jupyter.debugcell, jupyter.debugcontinue, jupyter.debugstop, jupyter.debugstepover 12:01:49.647 [debug] CodeLensFactory: Generating new code lenses for version 35 of document file://proton/AlgorithmGroup/Users/~/projects/InstrumentDifferences/python/script_usepartial.py for commands jupyter.runcell, jupyter.runallcellsabove, jupyter.debugcell, jupyter.debugcontinue, jupyter.debugstop, jupyter.debugstepover 12:01:53.798 [debug] CodeLensFactory: Generating new code lenses for version 37 of document file://proton/AlgorithmGroup/Users/~/projects/InstrumentDifferences/python/script_usepartial.py for commands jupyter.runcell, jupyter.runallcellsabove, jupyter.debugcell, jupyter.debugcontinue, jupyter.debugstop, jupyter.debugstepover 12:01:56.908 [debug] CodeLensFactory: Generating new code lenses for version 38 of document file://proton/AlgorithmGroup/Users/~/projects/InstrumentDifferences/python/script_usepartial.py for commands jupyter.runcell, jupyter.runallcellsabove, jupyter.debugcell, jupyter.debugcontinue, jupyter.debugstop, jupyter.debugstepover 12:01:58.686 [debug] CodeLensFactory: Generating new code lenses for version 39 of document file://proton/AlgorithmGroup/Users/~/projects/InstrumentDifferences/python/script_usepartial.py for commands jupyter.runcell, jupyter.runallcellsabove, jupyter.debugcell, jupyter.debugcontinue, jupyter.debugstop, jupyter.debugstepover 12:01:59.704 [debug] CodeLensFactory: Generating new code lenses for version 41 of document file://proton/AlgorithmGroup/Users/~/projects/InstrumentDifferences/python/script_usepartial.py for commands jupyter.runcell, jupyter.runallcellsabove, jupyter.debugcell, jupyter.debugcontinue, jupyter.debugstop, jupyter.debugstepover 12:02:10.430 [trace] Executing silently Code (busy) = def _VSCODE_getVariable(what_to_get, is_debugging, *args):\n# Query Jupyter server for the info 12:02:12.604 [debug] CodeLensFactory: Generating new code lenses for version 42 of document file://proton/AlgorithmGroup/Users/~/projects/InstrumentDifferences/python/script_usepartial.py for commands jupyter.runcell, jupyter.runallcellsabove, jupyter.debugcell, jupyter.debugcontinue, jupyter.debugstop, jupyter.debugstepover 12:02:17.959 [debug] CodeLensFactory: Generating new code lenses for version 53 of document file://proton/AlgorithmGroup/Users/~/projects/InstrumentDifferences/python/script_usepartial.py for commands jupyter.runcell, jupyter.runallcellsabove, jupyter.debugcell, jupyter.debugcontinue, jupyter.debugstop, jupyter.debugstepover 12:02:18.409 [debug] CodeLensFactory: Generating new code lenses for version 55 of document file://proton/AlgorithmGroup/Users/~/projects/InstrumentDifferences/python/script_usepartial.py for commands jupyter.runcell, jupyter.runallcellsabove, jupyter.debugcell, jupyter.debugcontinue, jupyter.debugstop, jupyter.debugstepover 12:02:19.178 [debug] CodeLensFactory: Generating new code lenses for version 57 of document file://proton/AlgorithmGroup/Users/~/projects/InstrumentDifferences/python/script_usepartial.py for commands jupyter.runcell, jupyter.runallcellsabove, jupyter.debugcell, jupyter.debugcontinue, jupyter.debugstop, jupyter.debugstepover 12:02:19.862 [debug] CodeLensFactory: Generating new code lenses for version 58 of document file://proton/AlgorithmGroup/Users/~/projects/InstrumentDifferences/python/script_usepartial.py for commands jupyter.runcell, jupyter.runallcellsabove, jupyter.debugcell, jupyter.debugcontinue, jupyter.debugstop, jupyter.debugstepover 12:02:20.404 [debug] CodeLensFactory: Generating new code lenses for version 59 of document file://proton/AlgorithmGroup/Users/~/projects/InstrumentDifferences/python/script_usepartial.py for commands jupyter.runcell, jupyter.runallcellsabove, jupyter.debugcell, jupyter.debugcontinue, jupyter.debugstop, jupyter.debugstepover 12:02:20.888 [debug] CodeLensFactory: Generating new code lenses for version 61 of document file://proton/AlgorithmGroup/Users/~/projects/InstrumentDifferences/python/script_usepartial.py for commands jupyter.runcell, jupyter.runallcellsabove, jupyter.debugcell, jupyter.debugcontinue, jupyter.debugstop, jupyter.debugstepover 12:02:21.332 [debug] CodeLensFactory: Generating new code lenses for version 62 of document file://proton/AlgorithmGroup/Users/~/projects/InstrumentDifferences/python/script_usepartial.py for commands jupyter.runcell, jupyter.runallcellsabove, jupyter.debugcell, jupyter.debugcontinue, jupyter.debugstop, jupyter.debugstepover

Here are the logs after I "Run Cell" (using ctrl+Enter)

In the middle, I hovered over some functions in my file, which is what caused those four logs at 12:04

12:02:21.631 [info] Generated code for 35 = with 100 lines 12:02:21.634 [trace] Cell Index:35 sent to kernel 12:04:40.681 [trace] Executing silently Code (busy) = def _VSCODE_getVariable(what_to_get, is_debugging, args):\n# Query Jupyter server for the info 12:04:42.326 [trace] Executing silently Code (busy) = def _VSCODE_getVariable(what_to_get, is_debugging, args):\n# Query Jupyter server for the info 12:04:49.556 [trace] Executing silently Code (busy) = def _VSCODE_getVariable(what_to_get, is_debugging, args):\n# Query Jupyter server for the info 12:04:54.056 [trace] Executing silently Code (busy) = def _VSCODE_getVariable(what_to_get, is_debugging, args):\n# Query Jupyter server for the info 12:07:40.021 [trace] Executing silently Code (completed) = def _VSCODE_getVariable(what_to_get, is_debugging, args):\n# Query Jupyter server for the info with 1 output(s) 12:07:40.058 [trace] Executing silently Code (completed) = def _VSCODE_getVariable(what_to_get, is_debugging, args):\n# Query Jupyter server for the info with 1 output(s) 12:07:40.095 [trace] Executing silently Code (completed) = def _VSCODE_getVariable(what_to_get, is_debugging, args):\n# Query Jupyter server for the info with 1 output(s) 12:07:40.099 [trace] Start cell 35 execution @ 1720627660099 (clear output) 12:07:40.099 [debug] Kernel acknowledged execution of cell 35 @ 1720627660099 12:07:45.276 [trace] Cell 35 completed in 5.177s (start: 1720627660099, end: 1720627665276) 12:07:45.276 [trace] Cell 35 executed successfully 12:07:45.312 [trace] Executing silently Code (completed) = def _VSCODE_getVariable(what_to_get, is_debugging, args):\n# Query Jupyter server for the info with 1 output(s) 12:07:45.349 [trace] Executing silently Code (completed) = def _VSCODE_getVariable(what_to_get, is_debugging, args):\n# Query Jupyter server for the info with 1 output(s) 12:07:45.386 [trace] Executing silently Code (completed) = def _VSCODE_getVariable(what_to_get, is_debugging, args):\n# Query Jupyter server for the info with 1 output(s) 12:07:45.423 [trace] Executing silently Code (completed) = def _VSCODE_getVariable(what_to_get, is_debugging, *args):\n# Query Jupyter server for the info with 1 output(s)

ejohnsson6 commented 2 weeks ago

Do you have the variable explorer open? Might be related to #15838

goldrik commented 2 weeks ago

I dont have the variable explorer open in this case.

When a cell is pending (like I'd shown above) and I open the Jupyter Variable Explorer, no variables are shown, just the message "Loading variables". Then, after a few minutes, once the cell finally runs, the Variable Explorer populates with all the variables.