Add execution start and end time metadata for code cells

[Darshan808]

References #22

• Added execution start and end times to code cell metadata, visible when timing recording is enabled by user.
• Computed on the server side to ensure persistence even after the notebook is closed.

Screenshots

[github-actions]

👈 Launch a Binder on branch Darshan808/jupyter-server-nbmodel/add-execution-timing-metadata

[krassowski]

🚀 I think we would want to add a test, for example see:

jupyter-server-nbmodel/jupyter_server_nbmodel/tests/test_handlers.py

Line 79 in ef8181c

async def test_post_execute(jp_fetch, pending_kernel_is_ready, snippet, output):

since the exact timestamp will vary I would just check that the timing metadata is present and that the end time is greater than start time.

[krassowski]

For the metadata I think we will want to match the exact identifiers as used on the frontend, so instead of start_time we would use shell.execute_reply.started and for end time - shell.execute_reply - although these are less readable, it would make jupyter-server-nbmodel a drop-in replacement and compatible with existing extensions like jupyterlab-execute-time.

There also should be execution_failed for when the execution fails.

[Darshan808]

I think we would want to add a test, for example see:

For testing whether the metadata is being added correctly, we would need to pass ydoc: The YDoc jupyter server extension and metadata: Execution context. But during testing, we pass None and {} as their values due to which we get response from server but cell metadata is not added.

Can we somehow create dummy ydoc and metadata and pass it instead or do we have some other better way to do this?

[krassowski]

Can we somehow create dummy ydoc and metadata and pass it instead or do we have some other better way to do this?

You can change config to something like:

"ServerApp": {
    "jpserver_extensions": {
        "jupyter_server_ydoc": True,
        "jupyter_server_nbmodel": True,
        "jupyter_server_fileid": True,  # from jupyter_server_ydoc
    },
    "token": "",  # not sure if needed
    "disable_check_xsrf": True,   # not sure if needed
},

in

jupyter-server-nbmodel/conftest.py

Lines 3 to 12 in ef8181c

	pytest_plugins = ("pytest_jupyter.jupyter_server",)
	@pytest.fixture
	def jp_server_config(jp_server_config):
	return {
	"ServerApp": {
	"jpserver_extensions": {"jupyter_server_nbmodel": True, "jupyter_server_ydoc": False}
	}
	}

to enable jupyter_server_ydocand then I think you can access it from jp_serverapp.web_app.settings["jupyter_server_ydoc"] as in here, or using self.serverapp.extension_manager.extension_apps as in

jupyter-server-nbmodel/jupyter_server_nbmodel/extension.py

Lines 11 to 25 in ef8181c

	RTC_EXTENSIONAPP_NAME = "jupyter_server_ydoc"
	STOP_TIMEOUT = 3
	_request_id_regex = r"(?P<request_id>\w+-\w+-\w+-\w+-\w+)"
	class Extension(ExtensionApp):
	name = "jupyter_server_nbmodel"
	def initialize_handlers(self):
	rtc_extension = None
	rtc_extensions = self.serverapp.extension_manager.extension_apps.get(
	RTC_EXTENSIONAPP_NAME, set()
	)

You may also need to create a real collaborative notebook, for that purpose add jupyter_server_ydoc.pytest_plugin which will pull fixtures from https://github.com/jupyterlab/jupyter-collaboration/blob/main/projects/jupyter-server-ydoc/jupyter_server_ydoc/pytest_plugin.py and allow you to use rtc_create_notebook.

metadata: Execution context

Is this the same as we are sending from frontend? If so you should be able to populate it with cell_id, document_id and "record_timing": True.

[Darshan808]

This CI error seems similar to the one described in the jupyterlab/jupyter-collaboration#252.

[krassowski]

I think these are warnings, so I would not be too worried. I would focus on fixing

ERROR jupyter_server_nbmodel/tests/test_handlers.py::test_execution_timing_metadata - KeyError: 'file_id_manager'

[Darshan808]

I've spent considerable time and tried various methods to resolve the issue, but I still encounter an error stating "KeyError: 'event_logger'" in traitlets.

[krassowski]

It looks like the real problem is the timeout (you can see it if you scroll up):

________________________ test_execution_timing_metadata ________________________

jp_fetch = <function jp_fetch.<locals>.client_fetch at 0x7f20b5315bc0>
pending_kernel_is_ready = <function pending_kernel_is_ready.<locals>._ at 0x7f20b5315c60>
rtc_create_notebook = <function rtc_create_notebook.<locals>._inner at 0x7f20b5315ee0>
jp_serverapp = <jupyter_server.serverapp.ServerApp object at 0x7f20b5354fb0>

    @pytest.mark.timeout(TEST_TIMEOUT)
    async def test_execution_timing_metadata(jp_fetch, pending_kernel_is_ready, rtc_create_notebook, jp_serverapp):
        snippet = "a = 1"
        nb = nbformat.v4.new_notebook(
            cells=[nbformat.v4.new_code_cell(source=snippet, execution_count=1)]
        )
        nb_content = nbformat.writes(nb, version=4)
        path, _ = await rtc_create_notebook("test.ipynb", nb_content, store=True)
        collaboration = jp_serverapp.web_app.settings["jupyter_server_ydoc"]
        fim = jp_serverapp.web_app.settings["file_id_manager"]
        document = await collaboration.get_document(
            path=path, content_type="notebook", file_format="json", copy=False
        )
        doc = document.get()
        document_id = f'json:notebook:{fim.get_id("test.ipynb")}'
        cell_id = doc["cells"][0].get("id")
    
        r = await jp_fetch(
            "api", "kernels", method="POST", body=json.dumps({"name": NATIVE_KERNEL_NAME})
        )
        kernel = json.loads(r.body.decode())
        await pending_kernel_is_ready(kernel["id"])
    
>       response = await wait_for_request(
            jp_fetch,
            "api",
            "kernels",
            kernel["id"],
            "execute",
            method="POST",
            body=json.dumps({"code": snippet, "metadata":{"cell_id":cell_id,"document_id":document_id,"record_timing":True}}),
        )

jupyter_server_nbmodel/tests/test_handlers.py:175: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
jupyter_server_nbmodel/tests/test_handlers.py:41: in wait_for_request
    ans = await _wait_request(fetch, location)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

fetch = <function jp_fetch.<locals>.client_fetch at 0x7f20b5315bc0>
endpoint = '/api/kernels/c056[265](https://github.com/datalayer/jupyter-server-nbmodel/actions/runs/12688982252/job/35366715215?pr=29#step:7:266)5-7fb9-47f9-b827-161f37a61348/requests/7d2a5526-733f-478c-b057-b28e9f5c9952'

    async def _wait_request(fetch, endpoint: str):
        """Poll periodically to fetch the execution request result."""
        start_time = datetime.datetime.now()
        elapsed = 0.0
        while elapsed < 0.9 * TEST_TIMEOUT:
            await asyncio.sleep(SLEEP)
            response = await fetch(endpoint, raise_error=False)
            if response.code >= 400:
                response.rethrow()
            if response.code != 202:
                return response
    
            elapsed = (datetime.datetime.now() - start_time).total_seconds()
    
>       raise TimeoutError(f"Request {endpoint} timed out ({elapsed}s).")
E       TimeoutError: Request /api/kernels/c0562655-7fb9-47f9-b827-161f37a61348/requests/7d2a5526-733f-478c-b057-b28e9f5c9952 timed out (13.696742s).

jupyter_server_nbmodel/tests/test_handlers.py:31: TimeoutError

During handling of the above exception, another exception occurred:

>       lambda: ihook(item=item, **kwds), when=when, reraise=reraise
    )
E   pytest.PytestUnraisableExceptionWarning: Exception ignored in: <function MemoryObjectSendStream.__del__ at 0x7f20b96428e0>
E   
E   Traceback (most recent call last):
E     File "/opt/hostedtoolcache/Python/3.12.8/x64/lib/python3.12/site-packages/traitlets/traitlets.py", line 632, in get
E       value = obj._trait_values[self.name]
E               ~~~~~~~~~~~~~~~~~^^^^^^^^^^^
E   KeyError: 'event_logger'
E   
E   During handling of the above exception, another exception occurred:
E   
E   Traceback (most recent call last):
E     File "/opt/hostedtoolcache/Python/3.12.8/x64/lib/python3.12/site-packages/anyio/streams/memory.py", line 313, in __del__
E       warnings.warn(
E   ResourceWarning: Unclosed <MemoryObjectSendStream at 7f20b509e9f0>

It seems that it is stalling in the with ycell.doc.transaction(): context manager. I think I know what might be going on, will push a fix.

[krassowski]

It looks like test_post_input_execute causes other tests to fail randomly no matter what.

The tests are also failing on the main branch so this is not introduced by this PR. Below is an example where test_post_erroneous_execute fails. If I comment out test_post_input_execute then it passes:

=========================== short test summary info ============================
FAILED jupyter_server_nbmodel/tests/test_handlers.py::test_post_erroneous_execute[1 / 0-{"output_type": "error", "ename": "ZeroDivisionError", "evalue": "division by zero", "traceback": ["\\u001b[0;31m---------------------------------------------------------------------------\\u001b[0m", "\\u001b[0;31mZeroDivisionError\\u001b[0m                         Traceback (most recent call last)", "Cell \\u001b[0;32mIn[1], line 1\\u001b[0m\\n\\u001b[0;32m----> 1\\u001b[0m \\u001b[38;5;241;43m1\\u001b[39;49m\\u001b[43m \\u001b[49m\\u001b[38;5;241;43m/\\u001b[39;49m\\u001b[43m \\u001b[49m\\u001b[38;5;241;43m0\\u001b[39;49m\\n", "\\u001b[0;31mZeroDivisionError\\u001b[0m: division by zero"]}] - pytest.PytestUnraisableExceptionWarning: Exception ignored in: <function Socket.__del__ at 0x7f063fc5be20>
Traceback (most recent call last):
  File "/opt/hostedtoolcache/Python/3.12.8/x64/lib/python3.12/site-packages/traitlets/traitlets.py", line 632, in get
    value = obj._trait_values[self.name]
            ~~~~~~~~~~~~~~~~~^^^^^^^^^^^
KeyError: 'event_logger'
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
  File "/opt/hostedtoolcache/Python/3.12.8/x64/lib/python3.12/site-packages/zmq/sugar/socket.py", line 179, in __del__
    warn(
ResourceWarning: Unclosed socket <zmq.asyncio.Socket(zmq.DEALER) at 0x7f063cc9ee40>
PASSED jupyter_server_nbmodel/tests/test_handlers.py::test_post_execute[print('hello buddy')-{"output_type": "stream", "name": "stdout", "text": "hello buddy\\n"}]
PASSED jupyter_server_nbmodel/tests/test_handlers.py::test_post_execute[a = 1-]
PASSED jupyter_server_nbmodel/tests/test_handlers.py::test_post_execute[from IPython.display import HTML\nHTML('<p><b>Jupyter</b> rocks.</p>')-{"output_type": "execute_result", "metadata": {}, "data": {"text/plain": "<IPython.core.display.HTML object>", "text/html": "<p><b>Jupyter</b> rocks.</p>"}, "execution_count": 1}]
PASSED jupyter_server_nbmodel/tests/test_handlers.py::test_post_input_execute
=================== 1 failed, 4 passed, 1 warning in 14.57s ====================
Deleting active ExecutionStack. Be sure to call `await ExecutionStack.dispose()`.
/home/runner/work/jupyter-server-nbmodel/jupyter-server-nbmodel/jupyter_server_nbmodel/handlers.py:340: RuntimeWarning: coroutine 'ExecutionStack.dispose' was never awaited
  self.dispose()
RuntimeWarning: Enable tracemalloc to get the object allocation traceback
Could not destroy zmq context for <jupyter_client.asynchronous.client.AsyncKernelClient object at 0x7f063efd5df0>
Task was destroyed but it is pending!
task: <Task pending name='Task-124' coro=<_kernel_worker() running at /home/runner/work/jupyter-server-nbmodel/jupyter-server-nbmodel/jupyter_server_nbmodel/handlers.py:272> wait_for=<Future pending cb=[Task.task_wakeup()]>>
Exception ignored in: <coroutine object _kernel_worker at 0x7f063ceb5fe0>
Traceback (most recent call last):
  File "/home/runner/work/jupyter-server-nbmodel/jupyter-server-nbmodel/jupyter_server_nbmodel/handlers.py", line 301, in _kernel_worker
    raise to_raise
  File "/home/runner/work/jupyter-server-nbmodel/jupyter-server-nbmodel/jupyter_server_nbmodel/handlers.py", line 272, in _kernel_worker
    uid, snippet, metadata = await queue.get()
                             ^^^^^^^^^^^^^^^^^
  File "/opt/hostedtoolcache/Python/3.12.8/x64/lib/python3.12/asyncio/queues.py", line 160, in get
    getter.cancel()  # Just in case getter is not done yet.
    ^^^^^^^^^^^^^^^
  File "/opt/hostedtoolcache/Python/3.12.8/x64/lib/python3.12/asyncio/base_events.py", line 794, in call_soon
    self._check_closed()
  File "/opt/hostedtoolcache/Python/3.12.8/x64/lib/python3.12/asyncio/base_events.py", line 540, in _check_closed

[krassowski]

It looks like the relation is with number of tests and the teardown sequence. It seems that the kernel workers are not being properly terminated, but even adding manual call to stop_extension() at the end of each test does not help. This is looking quite tricky to solve, but probably best to solve it in another PR first.

[krassowski]

It seems that this is tracked in #16. Indeed running tests individually works.

[Darshan808]

Cell Execution Event has been implemented. This allows extensions to listen for the event and perform actions, such as notifying users when a cell execution is completed.

Could you please review it? Once everything is finalized, we can add tests and documentation.

[fcollonval]

Nicely done @Darshan808

I have a request to remove a duplicate code and a question about the timing. Otherwise this looks good to me.

[Darshan808]

Thanks for the suggestion @fcollonval, I applied the changes. Let me know if there are any other improvements to make!

[krassowski]

Tested locally against jupyterlab-execute-time - worked nicely on the first run! I noticed two issues:

• schedule time is not recorded (I opened Support timing indicating when cell execution got scheduled #30 to track this) - let's tackle it separately
• the execute metadata is never cleared, meaning that old and new timings get mixed up - this should be fixed here before we merge and release

[krassowski]

This looks good from my side, thank you @Darshan808!

@fcollonval good to merge?

[Darshan808]

When the notebook is closed and execution of a long-running cell completes, there is no way for extensions to offer notifications (e.g. sending an email)

Now that the ability for extensions to listen to cell execution events has been implemented, should we enhance a pre-built extension to add this notification functionality, or should we create a new extension like "jupyter-notifier"?

[krassowski]

Should we enhance a pre-built extension to add this notification functionality

No, there is too many opinionated choices to make. There are already a few extensions for notifications, once this PR gets released we can implement server-side triggered notifications in one of them :)

[fcollonval]

Thanks you both for this